> > 
> > The target process side is also hung:
> > 
> >  zsh           D 0000000000000002  3568  1288   1259 0x00000080
> >   ffff880078c57b98 0000000000000046 0000000000000000 0000000000011d4a
> >   ffff88006d4b8000 0000000000000000 ffff880078c57f50 00007fff138b0858
> >   ffff88006d4b83b8 000000000000f968 ffff88006d4b83b8 00000000001d5740
> >  Call Trace:
> >   [<ffffffff81097f6a>] ? gdb_uprobe_handler+0x79/0xc2
> >   [<ffffffff81097f6a>] ? gdb_uprobe_handler+0x79/0xc2
> >   [<ffffffff81097f6a>] ? gdb_uprobe_handler+0x79/0xc2
> >   [<ffffffff814225af>] __mutex_lock_common+0x207/0x38a
> >   [<ffffffff81097f6a>] ? gdb_uprobe_handler+0x79/0xc2
> >   [<ffffffff814227f0>] mutex_lock_nested+0x3c/0x41
> >   [<ffffffff81097f6a>] gdb_uprobe_handler+0x79/0xc2
> >   [<ffffffff810c8d09>] uprobe_report_signal+0x4e5/0x959
> >   [<ffffffff81077e53>] ? lock_release_holdtime+0x2c/0x11d
> >   [<ffffffff814239a0>] ? _spin_unlock+0x2b/0x30
> >   [<ffffffff81097293>] utrace_get_signal+0x33d/0x5bd
> >   [<ffffffff81061304>] ? get_signal_to_deliver+0x4c/0x3b6
> >   [<ffffffff810613ae>] get_signal_to_deliver+0xf6/0x3b6
> >   [<ffffffff8102e1f2>] ? kvm_clock_read+0x21/0x23
> >   [<ffffffff81010ffa>] do_notify_resume+0x89/0x746
> >   [<ffffffff812088de>] ? __up_read+0x76/0x7f
> >   [<ffffffff8142454a>] ? paranoid_userspace+0x39/0x5a
> >   [<ffffffff8107963a>] ? trace_hardirqs_on_caller+0x126/0x14a
> >   [<ffffffff8142455c>] paranoid_userspace+0x4b/0x5a
> > 
> > and the corresponding function call graph was:
> > 
> >   3854 zsh(1350): uprobe_report_signal action=0x0 engine=0xffff88003ac36078 
> > tsk=0xffff880037d0a470 regs=0xffff880059097f58 info
> >   3867 zsh(1350):  utrace_attach_pid pid=0xffff880078e8d680 flags=0x1 
> > ops=0xffffffff81443be0 data=0x0 
> >   3881 zsh(1350):   utrace_attach_task target=0xffff880037d0a470 flags=0x1 
> > ops=0xffffffff81443be0 data=0x0 
> >   3890 zsh(1350):    matching_engine utrace=0xffff880037d0aad8 flags=0x1 
> > ops=0xffffffff81443be0 data=0x0 
> >   3901 zsh(1350):    matching_engine return=0xffff880078d190f0 
> >   3907 zsh(1350):   utrace_attach_task return=0xffff880078d190f0 
> >   3914 zsh(1350):   put_task_struct t=0xffff880037d0a470 
> >   3918 zsh(1350):   put_task_struct 
> >   3923 zsh(1350):  utrace_attach_pid return=0xffff880078d190f0 
> 
> I can't think of why utrace_attach_pid() would get called here.

utrace_attach_pid is from xol_get_area(). So its clear that this was the
first time uprobe_report_signal was called. Also the call to
uretprobe_set_trampoline (below) confirms that this was the first time
uprobe_report_signal was called. 

> 
> >   3931 zsh(1350):  uretprobe_set_trampoline uproc=0xffff880075bc77e0 
> > tsk=0xffff880037d0a470 
> >   3947 zsh(1350):   kzalloc").call size=0x40 flags=? 
> >   3955 zsh(1350):   kzalloc").return return=0xffff88001ec27ee0 
> >   3986 zsh(1350):  uretprobe_set_trampoline 
> >   3999 zsh(1350):  clear_utrace_quiesce utask=0xffff880078f53290 resume=0x0 
> >   4007 zsh(1350):   utask_adjust_flags utask=0xffff880078f53290 set=0x0 
> > flags=0x1 
> >   4012 zsh(1350):   utask_adjust_flags 
> >   4017 zsh(1350):  clear_utrace_quiesce
> >   4028 zsh(1350):  uprobe_find_probept uproc=0xffff880075bc77e0 
> > vaddr=0x419dd0 
> >   4034 zsh(1350):  uprobe_find_probept return=0xffff8800377a4248 
> >   4041 zsh(1350):  gdb_uprobe_handler up=0xffff8800220c1660 
> > regs=0xffff880059097f58 
> >   4060 zsh(1350):  gdb_uprobe_handler 
> >   4073 zsh(1350):  utask_adjust_flags utask=0xffff880078f53290 set=0x1 
> > flags=0x1 
> >   4080 zsh(1350):   utrace_set_events_pid pid=0xffff880078e8d680 
> > engine=0xffff88003ac36078 eventmask=0x131d 
> >   4088 zsh(1350):    utrace_set_events target=0xffff880037d0a470 
> > engine=0xffff88003ac36078 events=0x131d 
> >   4095 zsh(1350):     get_utrace_lock target=0xffff880037d0a470 
> > engine=0xffff88003ac36078 attached=0x1 
> >   4108 zsh(1350):     get_utrace_lock return=0xffff880037d0aad8 
> >   4210 zsh(1350):    utrace_set_events return=0x0 
> >   4215 zsh(1350):   utrace_set_events_pid return=0x0 
> >   4220 zsh(1350):  utask_adjust_flags 
> >   4227 zsh(1350):  uprobe_put_process uproc=0xffff880075bc77e0 
> > in_callback=0x1 
> >   4232 zsh(1350):  uprobe_put_process return=0x0 
> >   4237 zsh(1350): uprobe_report_signal return=0x13 

return action from uprobes is 0x13 which is UTRACE_SIGNAL_IGN | 
UTRACE_SINGLESTEP
i.e ignore this signal because it was induced by uprobes and do a
singlestep.

> >   4242 zsh(1350): finish_callback utrace=0xffff880037d0aad8 
> > report=0xffff880059097d98 engine=0xffff88003ac36078 ret=0x13 
> >   4248 zsh(1350): finish_callback return=0x0 
> >   4254 zsh(1350): finish_resume_report report=0xffff880059097d98 
> > task=0xffff880037d0a470 utrace=0xffff880037d0aad8 
> >   4261 zsh(1350):  utrace_reset task=0xffff880037d0a470 
> > utrace=0xffff880037d0aad8 action=0xffff880059097d98 
> >   4268 zsh(1350):   put_detached_list list=0xffff880059097cc8 
> >   4273 zsh(1350):   put_detached_list 
> >   4278 zsh(1350):  utrace_reset 
> >   4284 zsh(1350):  utrace_stop task=0xffff880037d0a470 
> > utrace=0xffff880037d0aad8 report=0x0 
> 
> I'm confused here.  Is the traced task getting hung in
> gdb_uprobe_handler() -- per your call trace -- or utrace_stop() (or
> elsewhere) -- per your call graph?


So as per my analysis, gdb_utrace_report_signal was called, followed by
uprobe_report_signal. Since gdb_utrace_report_signal requested for
UTRACE_STOP as resume action for SIGTRAP, the thread got stopped.
uprobes was waiting for either the singlestep to occur (or the process to
exit/exec or some other event) before it could signal the process to be
quiesced. 

The unregistering thread (as pointed out by Jim) was waiting for the
thread to be set to be quiesced before it could complete the
unregistering.

--
Thanks and Regards
Srikar

> 
> > 
> > So it's as if there may be some sort of conflict between send_sig()
> > and unregister_uprobes(), but I'm not sure.  Do you have any initial
> > advice about what's supposed to work / not work, or what else to
> > instrument?
> > 

Reply via email to