Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow time response with pipes (Windows) #50

Open
vChavezB opened this issue Feb 27, 2021 · 5 comments
Open

Slow time response with pipes (Windows) #50

vChavezB opened this issue Feb 27, 2021 · 5 comments

Comments

@vChavezB
Copy link

vChavezB commented Feb 27, 2021

I am testing a program I developed for a Microcontroller with a Cortex-M4 CPU. As I need to read/write some specific variables in real time I decided to develop a GUI and use the xPack Qemu ARM software. This SW allows to emulate the microcontroller and interact as well with GDB. I am using pygdbmi to interrupt the program, write data from the GUI and read data and display it. I noticed the execution time of the complete process (interrupt >-read-memory-bytes>-write-memory-bytes>continue) takes around 1-0.6 seconds. As this represents lag in the GUI I decided to check if I could decrease the latency.

As I found out that there is support for GDB with a python API I created a script with a custom command that does what I need (interrupt>read>write>continue). Within the python script I measure the time it takes to execute and it was around 0.01-0.02 seconds. As I still need to integrate it to the GUI I tested two approaches:

  1. Use again pygdbmi and call the custom command I made in the python script. The response from the command is parsed through the pygdbmi library and the latency was between 1-0.4 seconds, which is a minor improvement.
  2. Use a file as a pipe and check if the latency comes from the pipes. In the python script for gdb I added method that writes a json file with the data I require. The only interaction with pipes in this case is to write to the standard input and send the command to the gdb process. To know if the script has finished I poll instead for the data contained in the json file. To my surprise this reduced the latency to almost the same I had by manually executing the python script (0.02-0.03) seconds.

So from these results and for my purpose, using files instead of pipes to retrieve the gbd response and the python script support for gdb I was able to have a faster GUI response for my simulated MCU. I could not test the results in Linux as I had troubles using a precompiled gdb with python support for my specific target (arm-none-eabi-gdb).

As I do not have experience with how pipes in Windows work I am not sure if this could be a issue related with windows pipes, the way pygdbmi gets responses from pipes in Windows , if the GDB Machine Interface is too slow or if my implementation is not as it should be. Just wanted to post the results of these experiments as maybe this can become useful to look for ways on reducing latency when interacting with GDB.

@leonardopsantos
Copy link

Hi there! I'm a bit confused by what exactly you mean by 'pipes'. Do you mean subprocess.PIPES, like in gdbcontroller?

        # Use pipes to the standard streams
        self.gdb_process = subprocess.Popen(
            self.command,
            shell=False,
            stdout=subprocess.PIPE,
            stdin=subprocess.PIPE,
            stderr=subprocess.PIPE,
            bufsize=0,
        )

From what I could understand from (2), you're saying that writing using stdin=subprocess.PIPE is very fast when you don't read back with stdout=subprocess.PIPE. I honestly don't see this as a problem unless we can really determine that stdout=subprocess.PIPE is slow and have a solution for that problem.

I'd start by profiling both solutions to check where exactly the extra time is being spent.

@vChavezB
Copy link
Author

What I meant with (2) is that I load a gdb python script with source my_gdb_py_script.py. Afterward, I activate the script by sending a custom command to GDB (loaded from the python script) through the python stdin pipe (subprocess.PIPE)- The script itself will interrupt the program, obtain values from the GDB python API method gdb.parse_and_eval(expr) write the results to a file and continue the program.

In python, I am just polling the file by checking for an ID number that I pass to the script, so if the file has the same ID I sent it through the custom command as an argument to the python script, it means that the GDB script finished processing the command. This takes around 20-30 ms roundtrip from command to getting the data.

In method (1) I use pygdbmi to send the following MI commands

  • interrupt
  • read-memory-bytes
  • write-memory-bytes
  • continue

which can take around 400 ms to 1000 ms.

Once I have time will check out the profiling suggestion and post the results. I might also consider using C/C++ directly to send the GDB MI commands and compare the latency.

Regards

@vChavezB
Copy link
Author

vChavezB commented May 30, 2021

I did some quick tests and from the profiling, I see that what takes most of the time is

IoManager.py:104(_get_responses_windows)

Makes sense as it has to wait for the response from the stdout. By measuring the time of each GDB command request I got the following times with the method time.time() from the time module of python

Command Time
"-exec-interrupt" ~1000 ms
"-data-read-memory-bytes" ~20 ms
"-data-write-memory-bytes" ~20 ms

Name of the script : pygdbmi_pipe.py
Cprofiling results:

 759920 function calls (759575 primitive calls) in 1.244 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.244    1.244 <string>:1(<module>)
        4    0.281    0.070    1.242    0.310 IoManager.py:104(_get_responses_windows)
       16    0.000    0.000    0.004    0.000 IoManager.py:181(_get_responses_list)
       48    0.000    0.000    0.000    0.000 IoManager.py:199(<lambda>)
        4    0.000    0.000    1.242    0.310 IoManager.py:216(write)
       16    0.000    0.000    0.000    0.000 IoManager.py:283(_buffer_incomplete_responses)
        4    0.000    0.000    1.242    0.310 IoManager.py:68(get_gdb_response)
       12    0.000    0.000    0.000    0.000 StringStream.py:10(__init__)
       90    0.000    0.000    0.000    0.000 StringStream.py:15(read)
       44    0.000    0.000    0.000    0.000 StringStream.py:28(seek)
       26    0.000    0.000    0.000    0.000 StringStream.py:32(advance_past_chars)
       18    0.000    0.000    0.000    0.000 StringStream.py:50(advance_past_string_with_gdb_escapes)
      262    0.000    0.000    0.000    0.000 __init__.py:1356(debug)
      262    0.000    0.000    0.000    0.000 __init__.py:1614(isEnabledFor)
        4    0.000    0.000    1.242    0.310 gdbcontroller.py:108(write)
       16    0.000    0.000    0.000    0.000 gdbmiparser.py:110(response_is_finished)
        2    0.000    0.000    0.001    0.000 gdbmiparser.py:193(_get_notify_msg_and_payload)
        4    0.000    0.000    0.000    0.000 gdbmiparser.py:207(_get_result_msg_and_payload)
      6/3    0.000    0.000    0.001    0.000 gdbmiparser.py:224(_parse_dict)
     21/8    0.000    0.000    0.001    0.000 gdbmiparser.py:282(_parse_key_val)
       21    0.000    0.000    0.000    0.000 gdbmiparser.py:300(_parse_key)
     23/8    0.000    0.000    0.001    0.000 gdbmiparser.py:314(_parse_val)
        2    0.000    0.000    0.000    0.000 gdbmiparser.py:353(_parse_array)
       12    0.000    0.000    0.001    0.000 gdbmiparser.py:41(parse_response)
       12    0.000    0.000    0.003    0.000 pprint.py:142(pformat)
    81/12    0.000    0.000    0.002    0.000 pprint.py:154(_format)
    15/11    0.000    0.000    0.001    0.000 pprint.py:180(_pprint_dict)
        1    0.000    0.000    0.000    0.000 pprint.py:207(_pprint_list)
        2    0.000    0.000    0.000    0.000 pprint.py:244(_pprint_str)
    15/11    0.000    0.000    0.001    0.000 pprint.py:333(_format_dict_items)
        1    0.000    0.000    0.000    0.000 pprint.py:350(_format_items)
      149    0.000    0.000    0.002    0.000 pprint.py:391(_repr)
      149    0.000    0.000    0.001    0.000 pprint.py:400(format)
  386/149    0.001    0.000    0.001    0.000 pprint.py:490(_safe_repr)
       12    0.000    0.000    0.003    0.000 pprint.py:55(pformat)
      366    0.000    0.000    0.000    0.000 pprint.py:84(__init__)
      281    0.000    0.000    0.000    0.000 pprint.py:87(__lt__)
      183    0.000    0.000    0.000    0.000 pprint.py:94(_safe_tuple)
       12    0.000    0.000    0.000    0.000 pprint.py:99(__init__)
      104    0.000    0.000    0.000    0.000 printcolor.py:27(fmt_green)
        1    0.000    0.000    1.244    1.244 pygdbmi_pipe.py:101(read_write)
        1    0.000    0.000    0.000    0.000 pygdbmi_pipe.py:24(__get_gdbmi_result)
        3    0.000    0.000    0.000    0.000 pygdbmi_pipe.py:34(__parse_mi_result)
        1    0.000    0.000    0.000    0.000 pygdbmi_pipe.py:41(__check_error)
        1    0.000    0.000    0.000    0.000 pygdbmi_pipe.py:63(get_console_out)
        1    0.000    0.000    0.200    0.200 pygdbmi_pipe.py:71(continue_program)
        1    0.000    0.000    1.000    1.000 pygdbmi_pipe.py:73(pause_program)
        4    0.000    0.000    1.242    0.310 pygdbmi_pipe.py:75(gdb_request)
        1    0.000    0.000    0.021    0.021 pygdbmi_pipe.py:84(write_memory)
        1    0.000    0.000    0.021    0.021 pygdbmi_pipe.py:91(read_memory)
        2    0.000    0.000    0.000    0.000 re.py:215(findall)
        2    0.000    0.000    0.000    0.000 re.py:271(_compile)
        1    0.000    0.000    1.244    1.244 {built-in method builtins.exec}
       36    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
      117    0.000    0.000    0.000    0.000 {built-in method builtins.id}
        6    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
       50    0.000    0.000    0.000    0.000 {built-in method builtins.issubclass}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.iter}
      206    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       12    0.000    0.000    0.000    0.000 {built-in method builtins.min}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.next}
        4    0.002    0.001    0.002    0.001 {built-in method builtins.print}
      356    0.000    0.000    0.000    0.000 {built-in method builtins.repr}
       44    0.000    0.000    0.001    0.000 {built-in method builtins.sorted}
        1    0.000    0.000    0.000    0.000 {built-in method fromhex}
   151101    0.019    0.000    0.019    0.000 {built-in method time.time}
      138    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
      149    0.000    0.000    0.000    0.000 {method 'copy' of 'dict' objects}
       16    0.000    0.000    0.000    0.000 {method 'decode' of 'bytes' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        4    0.000    0.000    0.000    0.000 {method 'encode' of 'str' objects}
       16    0.000    0.000    0.000    0.000 {method 'endswith' of 'bytes' objects}
        4    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'find' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'findall' of 're.Pattern' objects}
   302190    0.042    0.000    0.042    0.000 {method 'flush' of '_io._IOBase' objects}
       50    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
       34    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
       12    0.000    0.000    0.000    0.000 {method 'getvalue' of '_io.StringIO' objects}
       10    0.000    0.000    0.000    0.000 {method 'groups' of 're.Match' objects}
       44    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
       36    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
       55    0.000    0.000    0.000    0.000 {method 'match' of 're.Pattern' objects}
        2    0.000    0.000    0.000    0.000 {method 'pop' of 'list' objects}
   302186    0.895    0.000    0.895    0.000 {method 'readline' of '_io._IOBase' objects}
       16    0.000    0.000    0.000    0.000 {method 'replace' of 'bytes' objects}
       16    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'splitlines' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}
        4    0.000    0.000    0.000    0.000 {method 'write' of '_io.FileIO' objects}
      287    0.000    0.000    0.000    0.000 {method 'write' of '_io.StringIO' objects}

@vChavezB
Copy link
Author

vChavezB commented May 30, 2021

I did also a test for the Method (2) I mentioned above, where the only thing I send through stdin of the python Subprocess.PIPE is the custom python gdb command that does everything from the GDB side (pause, read,write,continue). Afterwards, I poll for a JSON file that should get me the output of the GDB script.

From these results, I would say that pygdbmi takes more time as it has to wait for the stdout from the GDB process. From this second test using a custom GDB python script all the processing is done internally by GDB with the GDB python API . This is just my guess as I would need to check the source code of GDB and understand how the python API for GDB works internally to confirm this hypothesis.

Name of the script: gdb_py_test.py
Cprofiling results:

1464 function calls in 0.046 seconds

   Ordered by: standard name
  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.046    0.046 <string>:1(<module>)
       70    0.000    0.000    0.007    0.000 __init__.py:274(load)
       70    0.000    0.000    0.002    0.000 __init__.py:299(loads)
       70    0.000    0.000    0.001    0.000 _bootlocale.py:11(getpreferredencoding)
       70    0.000    0.000    0.000    0.000 codecs.py:260(__init__)
       70    0.000    0.000    0.000    0.000 cp1252.py:22(decode)
        2    0.000    0.000    0.000    0.000 decoder.py:31(__init__)
       70    0.000    0.000    0.002    0.000 decoder.py:332(decode)
       70    0.001    0.000    0.001    0.000 decoder.py:343(raw_decode)
        1    0.000    0.000    0.046    0.046 gdb_py_test.py:131(request)
       70    0.003    0.000    0.045    0.001 gdb_py_test.py:14(read_py_gdb_out)
        1    0.000    0.000    0.046    0.046 gdb_py_test.py:141(request_profile)
        1    0.000    0.000    0.000    0.000 gdb_py_test.py:49(list_to_str)
        1    0.000    0.000    0.000    0.000 gdb_py_test.py:65(write)
       70    0.001    0.000    0.046    0.001 gdb_py_test.py:78(get_reply)
        1    0.000    0.000    0.000    0.000 gdb_py_test.py:89(read_write_request)
       70    0.000    0.000    0.000    0.000 {built-in method _codecs.charmap_decode}
       70    0.000    0.000    0.000    0.000 {built-in method _locale._getdefaultlocale}
        1    0.000    0.000    0.046    0.046 {built-in method builtins.exec}
       70    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
      118    0.000    0.000    0.000    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
       70    0.035    0.000    0.035    0.001 {built-in method io.open}
        2    0.000    0.000    0.000    0.000 {built-in method time.time}
        2    0.000    0.000    0.000    0.000 {method 'count' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'encode' of 'str' objects}
      138    0.000    0.000    0.000    0.000 {method 'end' of 're.Match' objects}
        1    0.000    0.000    0.000    0.000 {method 'flush' of '_io.BufferedWriter' objects}
      138    0.000    0.000    0.000    0.000 {method 'match' of 're.Pattern' objects}
       70    0.004    0.000    0.005    0.000 {method 'read' of '_io.TextIOWrapper' objects}
        2    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
       70    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'write' of '_io.BufferedWriter' objects}

@leonardopsantos
Copy link

I wrote a pull request to fix a different timing issue, but it might help you. The current _get_responses_windows uses a hack to make the Windows pipe non-blocking. My PR uses a second thread that pushes to a Queue. Do you mind trying my PR to see if it helps?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants