Bug 479191 - vgdb is blocked after several tries
Summary: vgdb is blocked after several tries
Status: REPORTED
Alias: None
Product: valgrind
Classification: Developer tools
Component: massif (show other bugs)
Version: 3.22 GIT
Platform: Other Other
: NOR normal
Target Milestone: ---
Assignee: Nicholas Nethercote
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-12-30 17:22 UTC by Fred M
Modified: 2024-01-02 14:34 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments
valgrind -d -d -d logs (131.65 KB, application/x-compressed)
2024-01-02 14:34 UTC, Fred M
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Fred M 2023-12-30 17:22:42 UTC
Hello,
I have a strange behavior with a specific program, on the second vgdb request, the vgdb is blocking.
I runned with "vgdb -d" to have more log, maybe the current log would be clever for someone ?


SUMMARY
***

valgrind '--tool=massif' '--time-unit=ms' '--vgdb=yes' '--vgdb-error=0' '--trace-children=yes' '--threshold=0.01' '--detailed-freq=1' '--massif-out-file=/tmp/massif.out' '--peak-inaccuracy=0.0' '--max-snapshots=1000' my_progs
==4685== Massif, a heap profiler
==4685== Copyright (C) 2003-2017, and GNU GPL'd, by Nicholas Nethercote
==4685== Using Valgrind-3.22.0.GIT and LibVEX; rerun with -h for copyright info
==4685== Command:
==4685== (action at startup) vgdb me ... 
==4685==   target remote | /usr/libexec/valgrind/../../bin/vgdb --pid=4685

//first vgdb OK 
vgdb -d '--cmd-time-out=2' detailed_snapshot /tmp/massif2023-12-30_17-56-45_0.out
17:57:08.067721 searching pid in directory /tmp/ format /tmp/vgdb-pipe-from-vgdb-to-
17:57:08.069624 check_trial 0 
17:57:08.070003 vgdb: using /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? /tmp/vgdb-pipe-to-vgdb-from-5122-by-root-on-??? /tmp/vgdb-pipe-shared-mem-vgdb-5122-by-root-on-???
17:57:08.070295 opening /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? write to pid
17:57:08.070511 opened /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? write to pid fd 4
17:57:08.070653 opening /tmp/vgdb-pipe-to-vgdb-from-5122-by-root-on-??? read cmd result from pid
17:57:08.070755 opened /tmp/vgdb-pipe-to-vgdb-from-5122-by-root-on-??? read cmd result from pid fd 5
sending command detailed_snapshot /tmp/massif2023-12-30_17-56-45_0.out to pid 5122
17:57:08.072446 OK packet rcvd
17:57:08.072597 nr received signals: sigint 0 sigterm 0 sighup 0 sigpipe 0
17:57:08.072647 joining with invoke_gdbserver_in_valgrind_thread

//Second vgdb blocked
vgdb -d '--cmd-time-out=2' detailed_snapshot /tmp/massif2023-12-30_17-56-45_1.out
18:02:11.219325 searching pid in directory /tmp/ format /tmp/vgdb-pipe-from-vgdb-to-
18:02:11.219495 check_trial 0 
18:02:11.219752 vgdb: using /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? /tmp/vgdb-pipe-to-vgdb-from-5122-by-root-on-??? /tmp/vgdb-pipe-shared-mem-vgdb-5122-by-root-on-???
18:02:11.220031 opening /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? write to pid
18:02:11.220079 opened /tmp/vgdb-pipe-from-vgdb-to-5122-by-root-on-??? write to pid fd 4
18:02:11.220127 opening /tmp/vgdb-pipe-to-vgdb-from-5122-by-root-on-??? read cmd result from pid
18:02:11.320018 IO for command started
18:02:11.421249 waitstopped attach main pid before waitpid signal_expected 19 - 
status 0x137f WIFSTOPPED 19 
18:02:11.461675 examining thread entries from tid 1 to tid 499
18:02:11.461912 found tid 1 status VgTs_WaitSys lwpid 5122
18:02:11.461963 found tid 2 status VgTs_WaitSys lwpid 5171
18:02:11.461986 attach_thread PTRACE_ATTACH pid 5171
18:02:11.462028 waitstopped attach_thread before waitpid signal_expected 19
18:02:11.463665 after waitpid pid 5171 p 5171 status 0x137f WIFSTOPPED 19 
18:02:11.463838 found tid 3 status VgTs_WaitSys lwpid 5274
18:02:11.463887 attach_thread PTRACE_ATTACH pid 5274
18:02:11.463924 waitstopped attach_thread before waitpid signal_expected 19
18:02:11.463953 after waitpid pid 5274 p 5274 status 0x137f WIFSTOPPED 19 
18:02:11.463986 found tid 4 status VgTs_WaitSys lwpid 5184
18:02:11.464069 attach_thread PTRACE_ATTACH pid 5184
18:02:11.495196 waitstopped attach_thread before waitpid signal_expected 19
18:02:11.496582 after waitpid pid 5184 p 5184 status 0x137f WIFSTOPPED 19 
18:02:11.496806 found tid 5 status VgTs_WaitSys lwpid 5204
CH pid 5204
18:02:11.496951 waitstopped attach_thread before waitpid signal_expected 19
18:02:11.497011 after waitpid pid 5204 p 5204 status 0x137f WIFSTOPPED 19 
18:02:11.501070 getregs regs_bsz 72
18:02:11.501129 PTRACE_GETREGSET defined, not used (yet?) by vgdb
18:02:11.501151 getregs PTRACE_GETREGS
18:02:11.501173 detected a working PTRACE_GETREGS
18:02:11.501195 setregs regs_bsz 72
18:02:11.501216 setregs PTRACE_SETREGS
18:02:11.501237 PTRACE_CONT to invoke
18:02:11.501261 waitstopped waitpid status after PTRACE_CONT to invoke before waitpid signal_expected 19
Comment 1 Paul Floyd 2023-12-30 20:14:27 UTC
Are you trying to attach two vgdbs to the same massif process?
Comment 2 Philippe Waroquiers 2023-12-31 13:27:36 UTC
On what are you running ? (processor, linux version, ...).

The difference between the first and second vgdb trace is that in the second case,
the threads are blocked in a system call, and vgdb has to do more complex operations to
wake up valgrind.

Also, you launch valgrind with --vgdb-error=0. 
This allows to do some gdb/vgdb operations before startup.
What is the reason for this in your case ?


If you put two -d options, vgdb will output more debugging info.

Also, you might add debugging options (-v -v -v -d -d -d) at valgrind side to see what happens there.
Comment 3 Fred M 2024-01-02 14:34:16 UTC
Created attachment 164625 [details]
valgrind -d -d -d logs

Hello,

[What is the reason for this in your case ?]
For no reason, I could retry without it if needed.

[chipset] Arm 
[linux] kernel 4.9  glibc 2.24

I re-run, (Please find the log in attachment )
valgrind -v -v -v -d -d -d --tool=massif --time-unit=ms --vgdb=yes --trace-children=yes --threshold=0.01 --vgdb-error=0  my_progs > /tmp
/valgrind_log.txt 2>&1

// vgdb ok : 
vgdb -d detailed_snapshot /tmp/test
15:27:55.768100 searching pid in directory /tmp/ format /tmp/vgdb-pipe-from-vgdb-to-
15:27:55.768392 check_trial 0 
15:27:55.768578 vgdb: using /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? /tmp/vgdb-pipe-to-vgdb-from-5313-by-root-on-??? /tmp/vgdb-pipe-shared-mem-vgdb-5313-by-root-on-???
15:27:55.768756 opening /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? write to pid
15:27:55.768809 opened /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? write to pid fd 4
15:27:55.768872 opening /tmp/vgdb-pipe-to-vgdb-from-5313-by-root-on-??? read cmd result from pid
15:27:55.769010 opened /tmp/vgdb-pipe-to-vgdb-from-5313-by-root-on-??? read cmd result from pid fd 5
sending command detailed_snapshot /tmp/test to pid 5313
--5313-- XT_massif_print detailed
--5313-- iteration 1
--5313-- XT_print_massif ms_ec n_ec 1
--5313-- XT_massif_print producing depth 0 groups
--5313-- depth 0 n_groups 1 n_insig 0
--5313-- XT_massif_print outputting 1 depth 0 groups
--5313-- depth 1 n_groups 0 n_insig 0
15:27:55.770032 OK packet rcvd
15:27:55.770083 nr received signals: sigint 0 sigterm 0 sighup 0 sigpipe 0
15:27:55.770118 joining with invoke_gdbserver_in_valgrind_thread
/root # 

/root # ls -ltr /tmp/
[...]
prw-------    1 root     root             0 Jan  2 15:27 vgdb-pipe-to-vgdb-from-5313-by-root-on-???
-rw-------    1 root     root            36 Jan  2 15:27 vgdb-pipe-shared-mem-vgdb-5313-by-root-on-???
prw-------    1 root     root             0 Jan  2 15:27 vgdb-pipe-from-vgdb-to-5313-by-root-on-???
-rw-r--r--    1 root     root           760 Jan  2 15:27 test
-rw-r--r--    1 root     root       1967966 Jan  2 15:28 valgrind_log.txt

// vgdb ko : 
/root # vgdb -d detailed_snapshot /tmp/test
15:28:14.104760 searching pid in directory /tmp/ format /tmp/vgdb-pipe-from-vgdb-to-
15:28:14.105576 check_trial 0 
15:28:14.105888 vgdb: using /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? /tmp/vgdb-pipe-to-vgdb-from-5313-by-root-on-??? /tmp/vgdb-pipe-shared-mem-vgdb-5313-by-root-on-???
15:28:14.106192 opening /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? write to pid
15:28:14.106279 opened /tmp/vgdb-pipe-from-vgdb-to-5313-by-root-on-??? write to pid fd 4
15:28:14.106459 opening /tmp/vgdb-pipe-to-vgdb-from-5313-by-root-on-??? read cmd result from pid
15:28:14.206649 attach to 'main' pid 5313
15:28:14.206929 attach main pid PTRACE_ATTACH pid 5313
15:28:14.206979 waitstopped attach main pid before waitpid signal_expected 19
15:28:14.212162 after waitpid pid 5313 p 5313 status 0x137f WIFSTOPPED 19 
15:28:14.212292 examining thread entries from tid 1 to tid 499
15:28:14.212362 found tid 1 status VgTs_WaitSys lwpid 5313
15:28:14.212396 found tid 2 status VgTs_WaitSys lwpid 5425
15:28:14.212418 attach_thread PTRACE_ATTACH pid 5425
15:28:14.212453 waitstopped attach_thread before waitpid signal_expected 19
15:28:14.212574 after waitpid pid 5425 p 5425 status 0x137f WIFSTOPPED 19 
15:28:14.212616 found tid 3 status VgTs_WaitSys lwpid 5499
15:28:14.212638 attach_thread PTRACE_ATTACH pid 5499
15:28:14.212665 waitstopped attach_thread before waitpid signal_expected 19
15:28:14.212742 after waitpid pid 5499 p 5499 status 0x137f WIFSTOPPED 19 
15:28:14.212781 found tid 4 status VgTs_WaitSys lwpid 5431
15:28:14.212803 attach_thread PTRACE_ATTACH pid 5431
15:28:14.212828 waitstopped attach_thread before waitpid signal_expected 19
15:28:14.226020 after waitpid pid 5431 p 5431 status 0x137f WIFSTOPPED 19 
15:28:14.226214 found tid 5 status VgTs_WaitSys lwpid 5438
15:28:14.226241 attach_thread PTRACE_ATTACH pid 5438
15:28:14.226282 waitstopped attach_thread before waitpid signal_expected 19
15:28:14.230184 after waitpid pid 5438 p 5438 status 0x137f WIFSTOPPED 19 
15:28:14.234720 getregs regs_bsz 72
15:28:14.234895 PTRACE_GETREGSET defined, not used (yet?) by vgdb
15:28:14.234993 getregs PTRACE_GETREGS
15:28:14.235089 detected a working PTRACE_GETREGS
15:28:14.235182 setregs regs_bsz 72
15:28:14.235275 setregs PTRACE_SETREGS
15:28:14.235378 PTRACE_CONT to invoke
15:28:14.236057 waitstopped waitpid status after PTRACE_CONT to invoke before waitpid signal_expected 19