search

namhyung / uftrace

Function graph tracer for C/C++/Rust/Python
https://uftrace.github.io/slide/
GNU General Public License v2.0
3.05k stars 474 forks source link

uftrace is extremely slow #276

Open Alive-and-Well opened 6 years ago

Alive-and-Well commented 6 years ago

Hello, I want to race the function calls of the v8 engine within the chromium browser. I compiled chromium using -finstrument-functions. But when I want to record the function calls of chromium (e.g., uftrace -t 1m chromeium --no-sandbox --headless --disable-gpu about:blank). I kept uftrace running over night but it still did not finish. Do I miss anything?

Also if I want to trace all function calls within the v8 engine would the call look like the following? uftrace -t 40s -F v8::Shell::Main chromium -no-sandbox --headless --disable-gpu [some website]

Regards, Tobias

honggyukim commented 6 years ago

@Alive-and-Well Thanks for using uftrace. But unfortunately, uftrace cannot properly trace chrome browser as of yet. We plan to fix the problem but need some more time. Your problem seems that it's not because uftrace is slow but because it's just hanging at some point so doesn't proceed.

Alive-and-Well commented 6 years ago

@honggyukim thanks for your replay. Is there any workaround that I can trace JavaScript that uses functions provided by the browser (e.g., getElementById())?

honggyukim commented 6 years ago

getElementById actually goes through v8 binding layer to blink engine. Tracing across v8 and blink engines are one of my important goals in the near future. To the best of my knowledge, the binding layer is implemented based on WebIDL so you can read the document to understand it. https://www.chromium.org/blink/webidl

If you're interested in tracing standalone V8 or nodejs engine, I can help you with that.

Alive-and-Well commented 6 years ago

Thanks for your help. I will try to use the --trace flag v8 (and editing the chrome/v8 source code) to get the JavaScript stack trace. Unfortuanlly this won't give me a detailed output as uftrace.

namhyung commented 6 years ago

@Alive-and-Well Did you use the latest version of uftrace?

I kept uftrace running over night but it still did not finish.

I saw silimar report sometime ago but it was on old version of Ubuntu and current uftrace has a fix (or workaround) of it. Could you please rerun with -v option so that I can see where it's stuck?

Alive-and-Well commented 6 years ago

Well this is odd. If I run the program with -v, it does not terminate (see: https://pastebin.com/8sCp0ign). However, if I use -vvvit runs smoothly and terminates.

namhyung commented 6 years ago

Thanks for the info. But I can see some error messages at the end:

...
mcount: mcount setup done
...
mcount: shmem_finish: tid: 17098 seqnum = 0 curr = 0, nr_buf = 2 max_buf = 2
[1204/112547.577307:ERROR:browser_gpu_channel_host_factory.cc(123)] Failed to launch GPU process.
...

I guess it's because you missed --disable-gpu on the command line, right?

Anyway, the shmem_finish is called when a task is terminated, so the initialization is done and some tasks are running already. Could you please attach to the chrome process using gdb and show backtrace where it was stuck?

Alive-and-Well commented 6 years ago

I am not entirely sure what you want. If I attach gdb to chromium (gdb chrome) and than run the binary (run) it terminates normally. 


(gdb) run --headless --disable-gpu 
Starting program: /home/chromtest/chromium/src/out/Default/chrome --headless --disable-gpu
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fffe786d700 (LWP 30891)]
[New Thread 0x7fffe706c700 (LWP 30896)]
[New Thread 0x7fffe686b700 (LWP 30897)]
[New Thread 0x7fffe606a700 (LWP 30898)]
[New Thread 0x7fffe5869700 (LWP 30899)]
[New Thread 0x7fffe5068700 (LWP 30900)]
[New Thread 0x7fffe4867700 (LWP 30901)]
[New Thread 0x7fffe4066700 (LWP 30902)]
[New Thread 0x7fffe3865700 (LWP 30903)]
[New Thread 0x7fffe3064700 (LWP 30904)]
[New Thread 0x7fffe2863700 (LWP 30905)]
[New Thread 0x7fffe2062700 (LWP 30906)]
[New Thread 0x7fffe1861700 (LWP 30907)]
[New Thread 0x7fffe1060700 (LWP 30908)]
[New Thread 0x7fffe085f700 (LWP 30909)]
[New Thread 0x7fffe005e700 (LWP 30910)]
[New Thread 0x7fffdf85d700 (LWP 30911)]
[New Thread 0x7fffdf05c700 (LWP 30912)]
[New Thread 0x7fffde85b700 (LWP 30913)]
[1205/113341.041224:ERROR:gpu_process_transport_factory.cc(1009)] Lost UI shared context.
[New Thread 0x7fffde05a700 (LWP 30914)]
[New Thread 0x7fffd7f9d700 (LWP 30915)]
[New Thread 0x7fffd379b700 (LWP 30916)]
[1205/113341.134258:ERROR:instance.cc(49)] Unable to locate service manifest for metrics
[1205/113341.134412:ERROR:service_manager.cc(889)] Failed to resolve service name: metrics
[New Thread 0x7fffd2702700 (LWP 30917)]
[New Thread 0x7fffd1f01700 (LWP 30918)]
[New Thread 0x7fffd1700700 (LWP 30919)]
   1: ~+0(this=0x3c74e79140b9 <JSGlobal Object>) {
   1: } -> 0x3c74e796de61 <JSFunction (sfi = 0x193fa6b747b9)>
   1: ~+16(this=0x3c74e79140b9 <JSGlobal Object>, 0x3c74e796dea1 <Object map = 0x98e7fb0c1b1>, 0x3c74e79140b9 <JSGlobal Object>, 1) {
   2:  new ~InjectedScript+0(this=0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>) {
   2:  } -> 0x124d383822e1 <undefined>
   1: } -> 0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>
   1: ~+0(this=0x3c74e79140b9 <JSGlobal Object>) {
   1: } -> 0x3c74e7971b59 <String[20]: complete about:blank>
   1: ~wrapObject+0(this=0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>, 0x3c74e7971b59 <String[20]: complete about:blank>, 0x124d38382441 <String[0]: >, 0x124d383823f1 <false>, 0x124d383823f1 <false>) {
   2:  ~_wrapObject+0(this=0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>, 0x3c74e7971b59 <String[20]: complete about:blank>, 0x124d38382441 <String[0]: >, 0x124d383823f1 <false>, 0x124d383823f1 <false>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>) {
   3:   new ~InjectedScript.RemoteObject+0(this=0x3c74e7971ba9 <JSObject>, 0x3c74e7971b59 <String[20]: complete about:blank>, 0x124d38382441 <String[0]: >, 0x124d383822e1 <undefined>, 0x124d383823f1 <false>, 0x124d383823f1 <false>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>, 0x124d383822e1 <undefined>) {
   4:    ~isPrimitiveValue+0(this=0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>, 0x3c74e7971b59 <String[20]: complete about:blank>) {
   5:     ~_isHTMLAllCollection+0(this=0x3c74e7970389 <InjectedScript map = 0x98e7fb0c8e1>, 0x3c74e7971b59 <String[20]: complete about:blank>) {
   5:     } -> 0x124d383823f1 <false>
   4:    } -> 0x124d38382381 <true>
   3:   } -> 0x124d383822e1 <undefined>
   2:  } -> 0x3c74e7971ba9 <JSObject>
   1: } -> 0x3c74e7971ba9 <JSObject>
[Thread 0x7fffde85b700 (LWP 30913) exited]
[Thread 0x7fffdf85d700 (LWP 30911) exited]
[Thread 0x7fffe005e700 (LWP 30910) exited]
[Thread 0x7fffe085f700 (LWP 30909) exited]
[Thread 0x7fffe1060700 (LWP 30908) exited]
[Thread 0x7fffe1861700 (LWP 30907) exited]
[Thread 0x7fffe2062700 (LWP 30906) exited]
[Thread 0x7fffd7f9d700 (LWP 30915) exited]
[Thread 0x7fffde05a700 (LWP 30914) exited]
[Thread 0x7fffe686b700 (LWP 30897) exited]
[Thread 0x7fffe786d700 (LWP 30891) exited]
[Thread 0x7fffd1700700 (LWP 30919) exited]
[Thread 0x7fffd1f01700 (LWP 30918) exited]
[Thread 0x7fffd2702700 (LWP 30917) exited]
[Thread 0x7fffd379b700 (LWP 30916) exited]
[Thread 0x7fffdf05c700 (LWP 30912) exited]
[Thread 0x7fffe2863700 (LWP 30905) exited]
[Thread 0x7fffe3064700 (LWP 30904) exited]
[Thread 0x7fffe3865700 (LWP 30903) exited]
[Thread 0x7fffe4066700 (LWP 30902) exited]
[Thread 0x7fffe4867700 (LWP 30901) exited]
[Thread 0x7fffe5869700 (LWP 30899) exited]
[Thread 0x7fffe606a700 (LWP 30898) exited]
[Thread 0x7fffe706c700 (LWP 30896) exited]
[Thread 0x7ffff7f1ea80 (LWP 30890) exited]
[Inferior 1 (process 30890) exited normally]
namhyung commented 6 years ago

I mean that you run chrome with uftrace and if it's stuck, you could use gdb to attach to it.

Alive-and-Well commented 6 years ago

Does this help?

Console:

Running: 
uftrace -t 30ms --num-thread 15 /home/chromtest/chromium/src/out/Default/chrome --no-sandbox --headless --disable-gpu about:blank

[1205/114818.467882:ERROR:gpu_process_transport_factory.cc(1009)] Lost UI shared
[1205/114819.832087:ERROR:instance.cc(49)] Unable to locate service manifest for
[1205/114819.832704:ERROR:service_manager.cc(889)] Failed to resolve service nam

GDB:

Attaching to process 2145
[New LWP 2150]
[New LWP 2151]
[New LWP 2152]
[New LWP 2153]
[New LWP 2154]
[New LWP 2155]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f4fccb9970d in poll () at ../sysdeps/unix/syscall-template.S:84
84  ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) backtrace
#0  0x00007f4fccb9970d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000000414003 in poll (__timeout=1000, __nfds=1, __fds=0x7ffc67c37190)
    at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2  do_main_loop (pfd=pfd@entry=0x7ffc67c37540, ready=ready@entry=5, 
    opts=opts@entry=0x7ffc67c37730, pid=<optimized out>)
    at /home/chromtest/uftrace/cmd-record.c:1793
#3  0x00000000004153b1 in command_record (argc=argc@entry=10, 
    argv=argv@entry=0x7ffc67c37a18, opts=opts@entry=0x7ffc67c37730)
    at /home/chromtest/uftrace/cmd-record.c:1875
#4  0x0000000000415d9e in command_live (argc=argc@entry=10, 
    argv=argv@entry=0x7ffc67c37a18, opts=opts@entry=0x7ffc67c37730)
    at /home/chromtest/uftrace/cmd-live.c:162
#5  0x0000000000404b13 in main (argc=10, argv=0x7ffc67c37a18)
    at /home/chromtest/uftrace/uftrace.c:996
namhyung commented 6 years ago

Please attach to chrome instead of uftrace.

Alive-and-Well commented 6 years ago

chrome trace 

(gdb) backtrace
#0  0x00005650d03468dd in (anonymous namespace)::MaskPtr(void*) (p=0xffffeda0e0e884b9) at ../../third_party/tcmalloc/chromium/src/free_list.h:77
#1  0x00005650d0346870 in (anonymous namespace)::UnmaskPtr(void*) (p=0xffffeda0e0e884b9) at ../../third_party/tcmalloc/chromium/src/free_list.h:83
#2  0x00005650d0346653 in (anonymous namespace)::FL_Next_No_Check(void*) (t=0x125dad91fa20) at ../../third_party/tcmalloc/chromium/src/free_list.h:94
#3  0x00005650d0345ec0 in (anonymous namespace)::FL_Next(void*) (t=0x125dad91fa20) at ../../third_party/tcmalloc/chromium/src/free_list.h:116
#4  0x00005650d0346383 in (anonymous namespace)::FL_Pop(void**) (list=0x125da7d160c8) at ../../third_party/tcmalloc/chromium/src/free_list.h:130
#5  0x00005650d039be3e in (anonymous namespace)::ThreadCache::FreeList::Pop() (this=0x125da7d160c8)
    at ../../third_party/tcmalloc/chromium/src/thread_cache.h:209
#6  0x00005650d039bbbb in (anonymous namespace)::ThreadCache::Allocate(size_t, size_t) (this=0x125da7d16000, size=96, cl=6)
    at ../../third_party/tcmalloc/chromium/src/thread_cache.h:375
#7  0x00005650d039206d in (anonymous namespace)::do_malloc(size_t) (size=96)
    at ../../third_party/tcmalloc/chromium/src/tcmalloc.cc:1122
#8  0x00005650d03969fc in MallocBlock::Allocate(size_t, int) (size=32, type=-271733872) at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:518
#9  0x000056510c6ef6bd in tc_realloc(void*, size_t) (ptr=0x125db032c8e0, size=32) at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:1210
#10 0x00005650e5ec02ab in (anonymous namespace)::TCRealloc((anonymous namespace)---Type <return> to continue, or q <return> to quit---
::(anonymous namespace)::AllocatorDispatch const*, void*, size_t, void*) (address=0x125db032c8e0, size=32, context=0x0)
    at ../../base/allocator/allocator_shim_default_dispatch_to_tcmalloc.cc:33
#11 0x00005650e5ebfcc5 in ShimRealloc(void*, size_t, void*) (address=0x125db032c8e0, size=32, context=0x0) at ../../base/allocator/allocator_shim.cc:217
#12 0x00005650e5ebf065 in realloc(void*, size_t) (ptr=0x125db032c8e0, size=32)
    at ../../base/allocator/allocator_shim_override_libc_symbols.h:28
#13 0x00007f3d013b97dd in dd_append_len (dd=0x7ffde7cb1d70, str=0x7f3cba8397bf "Feature4nameEv", size=7) at /home/chromtest/uftrace/utils/demangle.c:260
#14 0x00007f3d013b98bd in dd_source_name (dd=dd@entry=0x7ffde7cb1d70)
    at /home/chromtest/uftrace/utils/demangle.c:1240
#15 0x00007f3d013bb343 in dd_unqualified_name (dd=0x7ffde7cb1d70)
    at /home/chromtest/uftrace/utils/demangle.c:1296
#16 0x00007f3d013bbf50 in dd_nested_name (dd=0x7ffde7cb1d70)
    at /home/chromtest/uftrace/utils/demangle.c:1322
#17 0x00007f3d013bc23b in dd_encoding (dd=0x7ffde7cb1d70)
    at /home/chromtest/uftrace/utils/demangle.c:1422
#18 0x00007f3d013bc793 in demangle_simple (str=0x7f3cba8397ae "_ZNK10extensions7Feature4nameEv") at /home/chromtest/uftrace/utils/demangle.c:1456
#19 0x00007f3d013bcd95 in demangle (str=0x7f3cba8397ae "_ZNK10extensions7Feature4nameEv") at /home/chromtest/uftrace/utils/demangle.c:1499
#20 0x00007f3d013b2aa8 in load_symtab (symtab=symtab@entry=0x7f3d015cc480 <symtabs+32>, filename=filename@entry=0x7f3d015ccb60 <exename> "/home/chromtest/chromi---Type <return> to continue, or q <return> to quit---
um/src/out/Default/chrome", offset=offset@entry=94905073262592, flags=<optimized out>) at /home/chromtest/uftrace/utils/symbol.c:364
#21 0x00007f3d013b482f in load_symtabs (symtabs=symtabs@entry=0x7f3d015cc460 <symtabs>, dirname=dirname@entry=0x0, filename=0x7f3d015ccb60 <exename> "/home/chromtest/chromium/src/out/Default/chrome")
    at /home/chromtest/uftrace/utils/symbol.c:912
#22 0x00007f3d013acd27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1118
#23 0x00007f3d013acd27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1224
#24 0x00007f3d015de6ba in call_init (l=<optimized out>, argc=argc@entry=5, argv=argv@entry=0x7ffde7cb2538, env=env@entry=0x7ffde7cb2568) at dl-init.c:72
#25 0x00007f3d015de7cb in _dl_init (env=0x7ffde7cb2568, argv=0x7ffde7cb2538, argc=5, l=<optimized out>) at dl-init.c:30
#26 0x00007f3d015de7cb in _dl_init (main_map=0x7f3d017f5168, argc=5, argv=0x7ffde7cb2538, env=0x7ffde7cb2568) at dl-init.c:120
#27 0x00007f3d015cec6a in _dl_start_user () at /lib64/ld-linux-x86-64.so.2
#28 0x0000000000000005 in  ()
#29 0x00007ffde7cb406e in  ()
#30 0x00007ffde7cb409e in  ()
#31 0x00007ffde7cb40ab in  ()
#32 0x00007ffde7cb40b6 in  ()
#33 0x00007ffde7cb40c4 in  ()
---Type <return> to continue, or q <return> to quit---
#34 0x0000000000000000 in  ()
namhyung commented 6 years ago

Thanks for doing this. But it seems the task runs the init code (meaning it's not stuck). How early did you attach to the chrome process after started? Is there any other thread stuck in the libmcount? It'd be nice if you could show info thread and backtrace of the suspicious thread(s) after some time.

Alive-and-Well commented 6 years ago

I attached "right" (manually getting the pid and running gdb) after starting chrome.

(gdb) thread apply all bt

Thread 1 (Thread 0x7f65d955fb40 (LWP 20576)):
#0  0x000055bc63c75c40 in AddressMap<int>::FindMutable(Key) (this=0x35445f394fc0, key=0x9) at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:335
#1  0x000055bc63c75963 in AddressMap<int>::Find(Key) const (this=0x35445f394fc0, key=0x3544614ecc20)
    at ../../third_party/tcmalloc/chromium/src/addressmap-inl.h:290
#2  0x000055bc63c75653 in MallocBlock::CheckLocked(int) const (this=0x3544614ecc00, type=-271733872)
    at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:414
#3  0x000055bc63c6e783 in MallocBlock::Check(int) const (this=0x3544614ecc00, type=-271733872)
    at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:753
#4  0x000055bc9ffc7653 in tc_realloc(void*, size_t) (ptr=0x3544614ecc20, size=48) at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:1199
#5  0x000055bc797982ab in (anonymous namespace)::TCRealloc((anonymous namespace)::(anonymous namespace)::AllocatorDispatch const*, void*, size_t, void*) (address=0x3544614ecc20, size=48, context=0x0)
    at ../../base/allocator/allocator_shim_default_dispatch_to_tcmalloc.cc:33
#6  0x000055bc79797cc5 in ShimRealloc(void*, size_t, void*) (address=0x3544614ecc20, size=48, context=0x0) at ../../base/allocator/allocator_shim.cc:217
#7  0x000055bc79797065 in realloc(void*, size_t) (ptr=0x3544614ecc20, size=48)
    at ../../base/allocator/allocator_shim_override_libc_symbols.h:28
---Type <return> to continue, or q <return> to quit---
#8  0x00007f65d92007dd in dd_append_len (dd=0x7ffee9faeaf0, str=0x35445f456320 "BindState", size=9) at /home/chromtest/uftrace/utils/demangle.c:260
#9  0x00007f65d92024cb in dd_unqualified_name (dd=0x7ffee9faeaf0)
    at /home/chromtest/uftrace/utils/demangle.c:1175
#10 0x00007f65d92024cb in dd_unqualified_name (dd=0x7ffee9faeaf0)
    at /home/chromtest/uftrace/utils/demangle.c:1257
#11 0x00007f65d9202f50 in dd_nested_name (dd=0x7ffee9faeaf0)
    at /home/chromtest/uftrace/utils/demangle.c:1322
#12 0x00007f65d920323b in dd_encoding (dd=0x7ffee9faeaf0)
    at /home/chromtest/uftrace/utils/demangle.c:1422
#13 0x00007f65d9203793 in demangle_simple (str=0x7f658cc68a41 "_ZN4base8internal9BindStateIMN7content5mojom59ControllerServiceWorker_DispatchFetchEvent_ProxyToResponderEFvN5blink5mojom24ServiceWorkerEventStatusENS_4TimeEEJNS0_13PassedWrapperINSt3__110unique_ptrIS"...) at /home/chromtest/uftrace/utils/demangle.c:1456
#14 0x00007f65d9203d95 in demangle (str=0x7f658cc68a41 "_ZN4base8internal9BindStateIMN7content5mojom59ControllerServiceWorker_DispatchFetchEvent_ProxyToResponderEFvN5blink5mojom24ServiceWorkerEventStatusENS_4TimeEEJNS0_13PassedWrapperINSt3__110unique_ptrIS"...) at /home/chromtest/uftrace/utils/demangle.c:1499
#15 0x00007f65d91f9aa8 in load_symtab (symtab=symtab@entry=0x7f65d9413480 <symtabs+32>, filename=filename@entry=0x7f65d9413b60 <exename> "/home/chromtest/chromium/src/out/Default/chrome", offset=offset@entry=94267598659584, flags=<optimized out>) at /home/chromtest/uftrace/utils/symbol.c:364
#16 0x00007f65d91fb82f in load_symtabs (symtabs=symtabs@entry=0x7f65d9413460 <sy---Type <return> to continue, or q <return> to quit---
mtabs>, dirname=dirname@entry=0x0, filename=0x7f65d9413b60 <exename> "/home/chromtest/chromium/src/out/Default/chrome")
    at /home/chromtest/uftrace/utils/symbol.c:912
#17 0x00007f65d91f3d27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1118
#18 0x00007f65d91f3d27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1224
#19 0x00007f65d94256ba in call_init (l=<optimized out>, argc=argc@entry=5, argv=argv@entry=0x7ffee9faf2b8, env=env@entry=0x7ffee9faf2e8) at dl-init.c:72
#20 0x00007f65d94257cb in _dl_init (env=0x7ffee9faf2e8, argv=0x7ffee9faf2b8, argc=5, l=<optimized out>) at dl-init.c:30
#21 0x00007f65d94257cb in _dl_init (main_map=0x7f65d963c168, argc=5, argv=0x7ffee9faf2b8, env=0x7ffee9faf2e8) at dl-init.c:120
#22 0x00007f65d9415c6a in _dl_start_user () at /lib64/ld-linux-x86-64.so.2
#23 0x0000000000000005 in  ()
#24 0x00007ffee9fb006e in  ()
#25 0x00007ffee9fb009e in  ()
#26 0x00007ffee9fb00ab in  ()
#27 0x00007ffee9fb00b6 in  ()
#28 0x00007ffee9fb00c4 in  ()
#29 0x0000000000000000 in  ()

(gdb) info thread
  Id   Target Id         Frame 
* 1    Thread 0x7f65d955fb40 (LWP 20576) "chrome" 0x000055bc63c75c40 in AddressMap<int>::FindMutable (this=0x35445f394fc0, key=0x9)
    at ../../third_party/tcmalloc/chromium/src/debugallocation.cc:335
namhyung commented 6 years ago

Hmm.. It still runs the init code so I couldn't find where the problem is. The first log you show said it already finished the init code. Also I suspect chrome process has more tasks - I guess one of them might be stuck and others wait for it..?

Alive-and-Well commented 6 years ago

I started chrome with the --single-process flag and got the following output.

(gdb) info thread
  Id   Target Id         Frame 
* 1    Thread 0x7fbbb1dcab40 (LWP 16324) "chrome" 0x00007fbbab26a9f9 in gelf_getsym () from /usr/lib/x86_64-linux-gnu/libelf.so.1
(gdb) thread apply all bt

Thread 1 (Thread 0x7fbbb1dcab40 (LWP 16324)):
#0  0x00007fbbab26a9f9 in gelf_getsym ()
    at /usr/lib/x86_64-linux-gnu/libelf.so.1
#1  0x00007fbbb1a649ea in load_symtab (symtab=symtab@entry=0x7fbbb1c7e480 <symtabs+32>, filename=filename@entry=0x7fbbb1c7eb60 <exename> "/home/chromtest/chromium/src/out/Default/chrome", offset=offset@entry=93995480313856, flags=<optimized out>) at /home/chromtest/uftrace/utils/symbol.c:316
#2  0x00007fbbb1a6682f in load_symtabs (symtabs=symtabs@entry=0x7fbbb1c7e460 <symtabs>, dirname=dirname@entry=0x0, filename=0x7fbbb1c7eb60 <exename> "/home/chromtest/chromium/src/out/Default/chrome")
    at /home/chromtest/uftrace/utils/symbol.c:912
#3  0x00007fbbb1a5ed27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1118
#4  0x00007fbbb1a5ed27 in mcount_init ()
    at /home/chromtest/uftrace/libmcount/mcount.c:1224
#5  0x00007fbbb1c906ba in call_init (l=<optimized out>, argc=argc@entry=6, argv=argv@entry=0x7fff867a9ed8, env=env@entry=0x7fff867a9f10) at dl-init.c:72
#6  0x00007fbbb1c907cb in _dl_init (env=0x7fff867a9f10, argv=0x7fff867a9ed8, argc=6, l=<optimized out>) at dl-init.c:30
#7  0x00007fbbb1c907cb in _dl_init (main_map=0x7fbbb1ea7168, argc=6, argv=0x7fff867a9ed8, env=0x7fff867a9f10) at dl-init.c:120
#8  0x00007fbbb1c80c6a in _dl_start_user () at /lib64/ld-linux-x86-64.so.2
---Type <return> to continue, or q <return> to quit---
#9  0x0000000000000006 in  ()
#10 0x00007fff867ac05d in  ()
#11 0x00007fff867ac08d in  ()
#12 0x00007fff867ac09a in  ()
#13 0x00007fff867ac0a5 in  ()
#14 0x00007fff867ac0b3 in  ()
#15 0x00007fff867ac0c4 in  ()
#16 0x0000000000000000 in  ()
namhyung commented 6 years ago

Is it still stuck in an infinite loop? If so, could you please show me the backtrace after, say, 10 minutes?

Alive-and-Well commented 6 years ago

I started chromium without --single-process:


(gdb) backtrace
#0  0x00007f9142aed70d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007f9146cef38c in g_main_context_iterate (priority=2147483647, n_fds=2, fds=0x3fd341ee4d0, timeout=<optimized out>, context=0x3fd350e9890)
    at /build/glib2.0-prJhLS/glib2.0-2.48.2/./glib/gmain.c:4135
#2  0x00007f9146cef38c in g_main_context_iterate (context=context@entry=0x3fd350e9890, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at /build/glib2.0-prJhLS/glib2.0-2.48.2/./glib/gmain.c:3835
#3  0x00007f9146cef49c in g_main_context_iteration (context=0x3fd350e9890, may_block=1) at /build/glib2.0-prJhLS/glib2.0-2.48.2/./glib/gmain.c:3901
#4  0x00007f9148feff09 in plthook_return ()
    at /home/chromtest/uftrace/arch/x86_64/plthook.S:55
#5  0x00007ffc63ccd1f0 in  ()
#6  0x0000000142b07836 in  ()
#7  0x000003fd29249410 in  ()
#8  0x000003fd1fe34e20 in  ()
#9  0x000003fd29249410 in  ()
#10 0x00017f9148fddfe4 in  ()
#11 0x0000000000000000 in  ()
(gdb) info thread
  Id   Target Id         Frame 
* 1    Thread 0x7f9149348b40 (LWP 6543) "chrome" 0x00007f9142aed70d in poll ()
    at ../sysdeps/unix/syscall-template.S:84
  2    Thread 0x7f913894a700 (LWP 6910) "sandbox_ipc_thr" 0x00007f9142aed70d in poll () at ../sysdeps/unix/syscall-template.S:84
  3    Thread 0x7f9138149700 (LWP 6913) "NetworkChangeNo" 0x00007f9142af99d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  4    Thread 0x7f9137948700 (LWP 6914) "inotify_reader" 0x00007f9142aef593 in select () at ../sysdeps/unix/syscall-template.S:84
  5    Thread 0x7f9137127700 (LWP 6915) "TaskSchedulerSe" 0x00007f9142af99d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  6    Thread 0x7f91368e6700 (LWP 6916) "TaskSchedulerBa" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  7    Thread 0x7f91360a5700 (LWP 6917) "TaskSchedulerBa" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  8    Thread 0x7f9135864700 (LWP 6918) "TaskSchedulerFo" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  9    Thread 0x7f91347e2700 (LWP 6920) "TaskSchedulerFo" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
---Type <return> to continue, or q <return> to quit---
  10   Thread 0x7f91337a0700 (LWP 6922) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  11   Thread 0x7f9132f5f700 (LWP 6923) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  12   Thread 0x7f91326fe700 (LWP 6924) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  13   Thread 0x7f9131efd700 (LWP 6925) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  14   Thread 0x7f91316bc700 (LWP 6926) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  15   Thread 0x7f9130e5b700 (LWP 6927) "Chrome_IOThread" 0x00007f9142af99d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  16   Thread 0x7f91305da700 (LWP 6928) "TaskSchedulerSi" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  17   Thread 0x7f912fd99700 (LWP 6929) "CompositorTileW" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  18   Thread 0x7f912f558700 (LWP 6930) "AudioThread" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
  19   Thread 0x7f9129436700 (LWP 6931) "threaded-ml" 0x00007f9142aed70d in poll () at ../sysdeps/unix/syscall-template.S:84
  20   Thread 0x7f9123a90700 (LWP 6933) "gmain" 0x00007f9142aed70d in poll ()
    at ../sysdeps/unix/syscall-template.S:84
  21   Thread 0x7f912326f700 (LWP 6934) "gdbus" 0x00007f9142aed70d in poll ()
---Type <return> to continue, or q <return> to quit---
    at ../sysdeps/unix/syscall-template.S:84
  22   Thread 0x7f9122a2e700 (LWP 6935) "dconf worker" 0x00007f9142aed70d in poll () at ../sysdeps/unix/syscall-template.S:84
(gdb)
Alive-and-Well commented 6 years ago

I think the problem is the -t flag. If I run uftrace without the flag it terminates. But I get a Segmentation fault.

Running: 
uftrace --num-thread 15 /home/chromtest/chromium/src/out/Default/chrome --no-sandbox --headless --disable-gpu  about:blank

**child terminated by signal: 11: Segmentation fault**
# DURATION    TID     FUNCTION
            [ 9077] | std::__1::ios_base::Init::Init() {
            [ 9077] |   std::__1::__stdinbuf::__stdinbuf() {
            [ 9077] |     std::__1::basic_streambuf::basic_streambuf() {
            [ 9077] |       std::__1::locale::locale() {