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.

Sign up for GitHub

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

Jump to bottom

process hang #34

Closed
ceeaspb opened this issue Jul 17, 2014 · 3 comments
Closed

process hang #34

ceeaspb opened this issue Jul 17, 2014 · 3 comments
Labels
bug

Comments

@ceeaspb
Copy link

ceeaspb commented Jul 17, 2014

the profiler starts but hangs before the application starts doing any useful work.
this does not happen all the time.

here is gdb output attached to the running process:

(gdb) info threads
  Id   Target Id         Frame 
  14   Thread 0x7f1c9691c700 (LWP 6429) "java" 0x00007f1c95e18d3c in __lll_lock_wait_private () from /lib64/libc.so.6
  13   Thread 0x7f1c7e8cd700 (LWP 6430) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  12   Thread 0x7f1c7e7cc700 (LWP 6431) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  11   Thread 0x7f1c7db55700 (LWP 6432) "java" 0x00007f1c964fcab2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  10   Thread 0x7f1c7cfba700 (LWP 6433) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  9    Thread 0x7f1c7ceb9700 (LWP 6434) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  8    Thread 0x7f1c7cdb8700 (LWP 6435) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7    Thread 0x7f1c7ccb7700 (LWP 6436) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  6    Thread 0x7f1c7cbb6700 (LWP 6437) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5    Thread 0x7f1c7cab5700 (LWP 6438) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4    Thread 0x7f1c7c9b4700 (LWP 6439) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3    Thread 0x7f1c7c8b3700 (LWP 6440) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  2    Thread 0x7f1c7c7b2700 (LWP 6441) "java" 0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1    Thread 0x7f1c9691d740 (LWP 6428) "java" 0x00007f1c964f9f37 in pthread_join () from /lib64/libpthread.so.0
(gdb) thread 14
[Switching to thread 14 (Thread 0x7f1c9691c700 (LWP 6429))]
#0  0x00007f1c95e18d3c in __lll_lock_wait_private () from /lib64/libc.so.6
(gdb) where
#0  0x00007f1c95e18d3c in __lll_lock_wait_private () from /lib64/libc.so.6
#1  0x00007f1c95d97f66 in _L_lock_12192 () from /lib64/libc.so.6
#2  0x00007f1c95d954e1 in malloc () from /lib64/libc.so.6
#3  0x00007f1c9670e0a6 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2
#4  0x00007f1c942a6279 in CurrentJniEnv () at /home/vagrant/git/RichardWarburton/honest-profiler/src/main/cpp/globals.h:134
#5  Profiler::handle (this=0x7f1c900086a0, signum=<optimized out>, info=<optimized out>, context=0x7f1c969199c0) at /home/vagrant/git/RichardWarburton/honest-profiler/src/main/cpp/profiler.cpp:113
#6  <signal handler called>
#7  0x00007f1c95e05d87 in mprotect () from /lib64/libc.so.6
#8  0x00007f1c95d9414d in _int_malloc () from /lib64/libc.so.6
#9  0x00007f1c95d954ec in malloc () from /lib64/libc.so.6
#10 0x00007f1c95689448 in os::malloc(unsigned long, unsigned short, unsigned char*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#11 0x00007f1c9509f9d3 in ChunkPool::allocate(unsigned long, AllocFailStrategy::AllocFailEnum) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#12 0x00007f1c9509f0a1 in Arena::grow(unsigned long, AllocFailStrategy::AllocFailEnum) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#13 0x00007f1c950d4a47 in HandleArea::allocate_handle(oopDesc*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#14 0x00007f1c954232cd in initialize_static_field(fieldDescriptor*, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#15 0x00007f1c953cf897 in InstanceKlass::do_local_static_fields_impl(instanceKlassHandle, void (*)(fieldDescriptor*, Thread*), Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#16 0x00007f1c95425548 in java_lang_Class::create_mirror(KlassHandle, Handle, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#17 0x00007f1c95213c03 in ClassFileParser::parseClassFile(Symbol*, ClassLoaderData*, Handle, KlassHandle, GrowableArray<Handle>*, TempNewSymbol&, bool, Thread*) ()
   from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#18 0x00007f1c952177fd in ClassLoader::load_classfile(Symbol*, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#19 0x00007f1c957a02f0 in SystemDictionary::load_instance_class(Symbol*, Handle, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#20 0x00007f1c9579f3c6 in SystemDictionary::resolve_instance_class_or_null(Symbol*, Handle, Handle, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#21 0x00007f1c957a0783 in SystemDictionary::resolve_or_fail(Symbol*, Handle, Handle, bool, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#22 0x00007f1c9529c078 in ConstantPool::klass_at_impl(constantPoolHandle, int, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#23 0x00007f1c952a1670 in ConstantPool::klass_ref_at(int, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#24 0x00007f1c9556d891 in LinkResolver::resolve_pool(KlassHandle&, Symbol*&, Symbol*&, KlassHandle&, constantPoolHandle, int, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#25 0x00007f1c955742e5 in LinkResolver::resolve_invokestatic(CallInfo&, constantPoolHandle, int, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#26 0x00007f1c955771d5 in LinkResolver::resolve_invoke(CallInfo&, Handle, constantPoolHandle, int, Bytecodes::Code, Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#27 0x00007f1c95411aa2 in InterpreterRuntime::resolve_invoke(JavaThread*, Bytecodes::Code) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#28 0x00007f1c7ecac6c8 in ?? ()
#29 0x00007f1c7ecac683 in ?? ()
#30 0x00007f1c9691b778 in ?? ()
#31 0x00007f1c7d2a9368 in ?? ()
#32 0x00007f1c9691b7c8 in ?? ()
#33 0x00007f1c7d419a68 in ?? ()
#34 0x0000000000000000 in ?? ()




(gdb) thread 1
[Switching to thread 1 (Thread 0x7f1c9691d740 (LWP 6428))]
#0  0x00007f1c964f9f37 in pthread_join () from /lib64/libpthread.so.0
(gdb) where
#0  0x00007f1c964f9f37 in pthread_join () from /lib64/libpthread.so.0
#1  0x00007f1c962e4d15 in ContinueInNewThread0 () from /usr/lib/jvm/jdk1.8.0_05/bin/../lib/amd64/jli/libjli.so
#2  0x00007f1c962e063a in ContinueInNewThread () from /usr/lib/jvm/jdk1.8.0_05/bin/../lib/amd64/jli/libjli.so
#3  0x00007f1c962e3250 in JLI_Launch () from /usr/lib/jvm/jdk1.8.0_05/bin/../lib/amd64/jli/libjli.so
#4  0x0000000000400696 in main ()
(gdb) thread 11
[Switching to thread 11 (Thread 0x7f1c7db55700 (LWP 6432))]
#0  0x00007f1c964fcab2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) where
#0  0x00007f1c964fcab2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f1c9569102f in os::PlatformEvent::park(long) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#2  0x00007f1c9565044e in Monitor::IWait(Thread*, long) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#3  0x00007f1c95650a16 in Monitor::wait(bool, long, bool) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#4  0x00007f1c952926c7 in ConcurrentMarkSweepThread::wait_on_cms_lock_for_scavenge(long) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#5  0x00007f1c95292d30 in ConcurrentMarkSweepThread::run() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#6  0x00007f1c956920c8 in java_start(Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#7  0x00007f1c964f8df3 in start_thread () from /lib64/libpthread.so.0
#8  0x00007f1c95e0b3dd in clone () from /lib64/libc.so.6
(gdb) thread 7
[Switching to thread 7 (Thread 0x7f1c7ccb7700 (LWP 6436))]
#0  0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) where
#0  0x00007f1c964fc705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f1c9568bef3 in os::PlatformEvent::park() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#2  0x00007f1c956500f7 in Monitor::IWait(Thread*, long) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#3  0x00007f1c95650a96 in Monitor::wait(bool, long, bool) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#4  0x00007f1c952684ce in SurrogateLockerThread::loop() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#5  0x00007f1c957d503f in JavaThread::thread_main_inner() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#6  0x00007f1c957d5205 in JavaThread::run() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#7  0x00007f1c956920c8 in java_start(Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#8  0x00007f1c964f8df3 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f1c95e0b3dd in clone () from /lib64/libc.so.6
@ceeaspb
Copy link
Author

ceeaspb commented Jul 17, 2014

this seems to happen once every 15 times or so.

another backtrace (this time quoted!):

(gdb) thread 5
[Switching to thread 5 (Thread 0x7fdad1925700 (LWP 7188))]
#0  0x00007fdaf0e61d3c in __lll_lock_wait_private () from /lib64/libc.so.6
(gdb) bt
#0  0x00007fdaf0e61d3c in __lll_lock_wait_private () from /lib64/libc.so.6
#1  0x00007fdaf0de0f66 in _L_lock_12192 () from /lib64/libc.so.6
#2  0x00007fdaf0dde4e1 in malloc () from /lib64/libc.so.6
#3  0x00007fdaf17570a6 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2
#4  0x00007fdaef2ef279 in CurrentJniEnv () at /home/vagrant/git/RichardWarburton/honest-profiler/src/main/cpp/globals.h:134
#5  Profiler::handle (this=0x7fdae80086a0, signum=<optimized out>, info=<optimized out>, context=0x7fdad1921380) at /home/vagrant/git/RichardWarburton/honest-profiler/src/main/cpp/profiler.cpp:113
#6  <signal handler called>
#7  0x00007fdaf0e4ed87 in mprotect () from /lib64/libc.so.6
#8  0x00007fdaf0ddd14d in _int_malloc () from /lib64/libc.so.6
#9  0x00007fdaf0dde4ec in malloc () from /lib64/libc.so.6
#10 0x00007fdaf06d2448 in os::malloc(unsigned long, unsigned short, unsigned char*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#11 0x00007fdaf00e89d3 in ChunkPool::allocate(unsigned long, AllocFailStrategy::AllocFailEnum) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#12 0x00007fdaf00e80a1 in Arena::grow(unsigned long, AllocFailStrategy::AllocFailEnum) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#13 0x00007fdaf062f4e0 in Matcher::Label_Root(Node const*, State*, Node*, Node const*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#14 0x00007fdaf062f447 in Matcher::Label_Root(Node const*, State*, Node*, Node const*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#15 0x00007fdaf062f447 in Matcher::Label_Root(Node const*, State*, Node*, Node const*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#16 0x00007fdaf0630c8b in Matcher::match_tree(Node const*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#17 0x00007fdaf0631d86 in Matcher::xform(Node*, int) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#18 0x00007fdaf06346c5 in Matcher::match() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#19 0x00007fdaf0298dea in Compile::Code_Gen() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#20 0x00007fdaf02998ea in Compile::Compile(ciEnv*, TypeFunc const* (*)(), unsigned char*, char const*, int, bool, bool, bool) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#21 0x00007fdaf0768629 in OptoRuntime::generate_stub(ciEnv*, TypeFunc const* (*)(), unsigned char*, char const*, int, bool, bool, bool) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#22 0x00007fdaf0768856 in OptoRuntime::generate(ciEnv*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#23 0x00007fdaf01f03e9 in C2Compiler::initialize() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#24 0x00007fdaf02a0eca in CompileBroker::init_compiler_runtime() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#25 0x00007fdaf02a6d0f in CompileBroker::compiler_thread_loop() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#26 0x00007fdaf081e03f in JavaThread::thread_main_inner() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#27 0x00007fdaf081e205 in JavaThread::run() () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#28 0x00007fdaf06db0c8 in java_start(Thread*) () from /usr/lib/jvm/jdk1.8.0_05/jre/lib/amd64/server/libjvm.so
#29 0x00007fdaf1541df3 in start_thread () from /lib64/libpthread.so.0
#30 0x00007fdaf0e543dd in clone () from /lib64/libc.so.6

@jasonk000
Copy link

I think this might have been fixed by @nitsanw 's commit d1b36de , removed thread local storage for jni environment.

@RichardWarburton
Copy link
Member

In that case I'm closing the issue. If it still appears to be a bug, then please re-open ;)

janmejay pushed a commit to janmejay/fk-prof that referenced this issue Jul 10, 2017
@ankeetmaini
Shows percentages differently (jvm-profiling-tools#34)
92e6bd3
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@RichardWarburton @jasonk000 @ceeaspb