Can't profile pyinstaller binaries on OSX

[DurvalMenezes]

Getting an error here when I try to profile a running borg create (from borg backup) command:

# ps auwx | grep borg
   root  41144  51.8 57.8 33436416 29112884 s001  R+   10:15PM 303:15.77 borg create --checkpoint-interval=3600000 -v --show-rc --progress --stats ::20191212L210000 .
# py-spy record -o OUTPUT.svg -d 900 -p 41144

py-spy then spends the next 900s doing something (hopefully sampling the process) and then fails with the message Error: Failed to find python version from target process.

This happens when running the standard borg "binary" from the borg backup distribution, which 'encapsulates' everything needed for borg to run inside that binary, including the Python executable.

Using lsof, I'm able to determine the location of the Python interpreter binary, which in the above case was /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/_MEIkCvo55/Python; I suspect that path would change from one run to the other, but anyway I'm able to determine it before calling py-spy.

How can I proceed towards specifying this path to py-spy? I really need it in order to debug some really weird behavior we're seeing with borg backup.

Thanks in advance,
-- Durval.

[textshell]

Maybe relevant: borg uses pyinstaller for it's binary distribution.

[benfred]

This is related to pyinstaller on osx, specifically with pyinstaller bundling python built with the --enable-framework flag (linux was already working fine w/ #42).

The last commit should fix, will be in the next release.

The weird thing is that it took 15 minutes to fail. It should fail nearly instantly if it fails to find the python interpreter - and thats exactly what happened when I tried profiling borg with py-spy just now. Does a progress bar display during this 15 minutes ? Is py-spy using CPU ? Does it take exactly 15 minutes - can you run this with 'sudo time py-spy record -o OUTPUT.svg -d 900 -p 41144' to see how long its taking?

[DurvalMenezes]

@benfred no progress bar nor anything else but the message Error: Failed to find python version from target process after the long wait. Not sure it took exactly 15m, sure it was more than 14m and less than 15m (from my timings of other things I was doing at the time).

Just ran it again, once more on a borg create process, with the time command you requested, here's the complete transcript (NB: sudo was not really needed as I was already root at this point, but included it anyway just so as to use the exact command you requested):

# sudo time ~/py-spy record -o OUTPUT.svg -d 900 -p 73657
Error: Failed to find python version from target process

     1310.24 real         2.55 user      1306.44 sys
#

So it took 1310/60 =~ 21.8 ie almost 22 minutes this time around.

BTW, I tried bringing up a rust cross-compile environment so I could build your latest master (with the commit) on my development Linux notebook and have it run on the production MacOSX server (I know this sounds strange in a "the-other-way-around" manner, but it's just as things are here), to no avail: I kept getting weird errors from rustup, and had to give up when I burned through the time I had available to make it happen.

If you can, please let me know when a new py-spy binary with this fix already in it becomes available, and I will be more than happy to test it.

[benfred]

@DurvalMenezes That's bizarre, I really can't see why it's taking that long. I'm pretty confident that the last release will fix the error, but I'm worried that even with the fix we still might have that 20+ minute lag. Can you enable logging and paste the output? (```RUST_LOG=info py-spy record -o ...)

I've uploaded a binary that you you can test out the fix with. You can download/install on your mac with:

curl https://static.benfrederickson.com/py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl  -O 
pip install py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl

If you don't have pip installed you can just unzip py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl to get the binary too.

[DurvalMenezes]

@benfred many thanks for the prepared binary, and for the thoughtful, detailed comment. More, below:

Can you enable logging and paste the output? (```RUST_LOG=info py-spy record -o ...)

Just did it, see below.

If you don't have pip installed you can just unzip py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl to get the binary too.

No pip here on MacOSX's standard Python, so as per your advice that's what I did:

curl https://static.benfrederickson.com/py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl  -O 
     [...]
unzip -v py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl 
     Archive:  py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl
      Length   Method    Size  Cmpr    Date    Time   CRC-32   Name
     --------  ------  ------- ---- ---------- ----- --------  ----
      3888532  Defl:N  1451321  63% 12-15-2019 05:25 761e3164  py_spy-0.3.2.dev0.data/scripts/py-spy
      [...]
unzip py_spy-0.3.2.dev0-py2.py3-none-macosx_10_7_x86_64.whl  py_spy-0.3.2.dev0.data/scripts/py-spy
      [...]
      inflating: py_spy-0.3.2.dev0.data/scripts/py-spy  
sudo install -o root -g wheel -m 755  py_spy-0.3.2.dev0.data/scripts/py-spy  /usr/local/bin/py_spy-0.3.2.dev0

Just ran it as you requested, again on the running borg create process we're trying to figure out (alas, for the last two days it has refrained from acting up, see borgbackup/borg#4869 (comment) -- but I want to be ready when it acts up again):

export RUST_LOG='info py-spy record -o py-spy.rust_log'     
py_spy-0.3.2.dev0 record -o OUTPUT.svg -d 900 -p 19483
     Sampling process 100 times a second for 900 seconds. Press Control-C to exit.
 ������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������ 90000/90000
     Wrote flamegraph data to 'OUTPUT.svg'. Samples: 90000 Errors: 0
     LSOpenURLsWithRole() failed with error -10810 for the file /REDACTED/OUTPUT.svg.

The initial "Sampling process" message showed up almost immediately, followed by the weird control symbol "progress bar" and a counter that advanced all the way to 90000/90000.
I ignored the LSOpenURLsWithRole() error which I presume was py-spy's trying to open the SVG file on the X display for me (as this machine is basically headless and accessed over SSH), transferrd the resulting OUTPUT.svg file, and visuallized it on my notebook -- it seems OK, albeit I can't make much sense out of it -- but it should make sense for the borg developers, specially when I manage to capture a new one when the borg create process gets bogged down again.

To my dismay, I can't find the py-spy.rust_log file anywhere -- perhaps I misunderstood what you meant by -o ... on your request to set RUST_LOG? Could not find clear documentation on that environment variable to enlighten myself on this regard.

Anyway, it seems to be working now -- and without the initial 22-min lapse. The previous version still produces it before erroring out, so if you want a RUST_LOG output from it please let me know the exact command line (or the place where the produced file would be). If it would help, I can also run it under dtruss and send you sequence of system calls and timestamps called by the process.

To sum it up. Let me know how I can help and I will be glad to.

[benfred]

I think its weird that almost all of that 22 minutes is spent in syscalls rather than user code - and I'm wondering if the 22 minute initial lapse is related to the performance problem that you are trying to debug. Is the system otherwise pretty responsive during these problems, or is it painfully slow to do other basic operations?

Enabling logging would be done by export RUST_LOG=info or RUST_LOG=py-spy record -o output.svg -p 12345 (but not like you were doing). I don't think I need the logs though since it looks like it will work with the last commit.

[benfred]

that fix is in v0.3.2