[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has abandoned this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Abandoned Abandoning for now. Some work has gone into hdfs call timeouts in the form of IMPALA-7738. That should provide some relief for hdfs hangs. Will get back when I find time. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: abandon Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Zoram Thanga
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: I was looking into other stuff and this got sidetracked. Will address the comments and upload a new PS soon. I agree this will be very useful in RCA'ing hangs. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 21 Aug 2018 21:22:10 + Gerrit-HasComments: No
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: Any news on this? We continue to have a rash of places where namenode calls get stuck in various ways, so this would be very welcome there! -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Sat, 18 Aug 2018 00:16:38 + Gerrit-HasComments: No
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Todd Lipcon has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: btw for the Java stack tracing I'd also investigate implementing something in pure java, even if it has native hooks -- eg capture a JNI ref to the current Thread from a non-async context, and then when you want to stack trace that thread, call the java Thread.getStackTrace() API instead of using JVMTI. For these use cases of 5-second+ HDFS calls, I don't think you're looking for super-low-latency-low-overhead stack collection as provided by signals, and the public Java APIs are probably enough? -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 12 Jul 2018 19:46:29 + Gerrit-HasComments: No
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Todd Lipcon has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: (9 comments) http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/debug-util.cc File be/src/kudu/util/debug-util.cc: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/debug-util.cc@62 PS4, Line 62: DEFINE_int32(stack_trace_sig_num, SIGRTMIN, "Signal used by the thread watchdog to " this is already settable in the Kudu version of the code by just calling SetStackTraceSignal(). We have it defined by an API instead of a flag because this code ends up linked into our client, etc, and we need it to be programmatically settable (the client has no command line). Is there some reason you couldn't use the existing API call, and put this flag in Impala's initialization sequence? http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/debug-util.cc@122 PS4, Line 122: // TODO: Implement this as a callback rather than polluting Kudu's util code? if you put it behind an ifdef of some kind that would be fine, and maybe easier than refactoring http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/debug-util.cc@272 PS4, Line 272: std::stringstream ret; why make this change? seems unnecessary. we usually avoid std::stringstream http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/kernel_stack_watchdog.cc File be/src/kudu/util/kernel_stack_watchdog.cc: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/kernel_stack_watchdog.cc@135 PS4, Line 135: // TODO: Implement an exponential backoff? why? if we can't get it immediately, then backing off and trying later probably won't be successful either, and the actual timing becomes inaccurate http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/kudu/util/kernel_stack_watchdog.cc@151 PS4, Line 151: << "User stack:\n" << user_stack << "\n"; glog already puts a \n at the end of log messages, this shouldn't be necessary http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/runtime/io/handle-cache.inline.h File be/src/runtime/io/handle-cache.inline.h: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/runtime/io/handle-cache.inline.h@34 PS4, Line 34: SCOPED_WATCHDOG(); you don't want some string in here indicating which file it's trying to open or somesuch? http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/service/jvmti-agent.cc File be/src/service/jvmti-agent.cc: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/service/jvmti-agent.cc@27 PS4, Line 27: // by adding "-agentpath: to the JVM commandline does this then prevent loading of any other java agents in impala? Do you actually need this separate shared library to do this even in the case where you are embedding the JVM? http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/util/jvm-stack-trace.h File be/src/util/jvm-stack-trace.h: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/util/jvm-stack-trace.h@46 PS4, Line 46: void Collect(); this should document whether it's safe to be called from async context (signal handler) http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/util/jvm-stack-trace.cc File be/src/util/jvm-stack-trace.cc: http://gerrit.cloudera.org:8080/#/c/10696/4/be/src/util/jvm-stack-trace.cc@65 PS4, Line 65: jvmtiEnv* jvmti = JVMTIState::GetInstance()->GetJVMTI(); How do you know that all of the functions used in this method are async-safe? Are they documented as such somewhere? The profilers I've seen use VM::_asyncGetCallTrace() for this purpose, not jvmti methods. Comments in the async-profiler project seem to indicate these calls may not be safe in async context: https://github.com/jvm-profiling-tools/async-profiler/blob/master/src/profiler.cpp#L249 https://github.com/jvm-profiling-tools/async-profiler/blob/master/src/profiler.cpp#L344 I think all the stack collection should be stress-tested by starting a thread which does stack traces of all other threads in a near-tight loop while running various Impala workloads. We found a lot of complex bugs causing hangs and crashes with this case. See debug-util-test.cc "DangerousOperationThread". -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 12 Jul 2018 19:43:33 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (4 comments) http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc File be/src/kudu/util/debug-util.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@62 PS3, Line 62: DEFINE_int32(stack_trace_sig_num, SIGRTMIN, "Signal used by the thread watchdog to " > Firstly, these changes in Kudu's util code are expected to be pushed to the I'm all for configurability in Kudu's code. My point is that Impala users have no possible reason to configure this. (It's useful to turn it off entirely perhaps, but choosing which signal to use makes no sense to an end user.) http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@288 PS3, Line 288: ret << g_comm.jstack.Stringify(); > We do have a kill switch for this whole watchdog feature. Do we need to hav I'm fine with just having one big one. http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt File be/src/service/CMakeLists.txt: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt@53 PS3, Line 53: # Jvmti agent library that registers with the JVM on load. > I don't think there is much overhead in the binary size. I'm not sure I und 225K is true is fine. That's in a statically linked build? See https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/invocation.html#JNJI_OnLoad and look for "JNI_OnLoad_L". http://gerrit.cloudera.org:8080/#/c/10696/3/bin/impala-config.sh File bin/impala-config.sh: http://gerrit.cloudera.org:8080/#/c/10696/3/bin/impala-config.sh@619 PS3, Line 619: LIBHDFS_OPTS+=" -agentpath:$IMPALA_HOME/be/build/latest/service/libjvmtiagent.so" > I commented about the binary sizes in the other file. If we at all can, we should avoid placing additional burden on our users to configure things that they shouldn't need to configure. If we want our binary to always run with this agent, we should configure it programmatically if at all possible. I think the reason it may be painful is because of HDFS-12628, but we should look into it. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 06 Jul 2018 21:39:12 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: Working on rebasing this patch on to an upcoming Kudu rebase. The Kudu code, in this case, changed quite a bit. Also looking into making minimal changes to the kudu-util code so that it helps future rebases. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 28 Jun 2018 22:09:24 + Gerrit-HasComments: No
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 4: Forgot to respond to the top-level comment. > The big question for me is what our policy is here. Should we be doing this > for all blocking system calls? All blocking RPCs? How do we maintain that we > have decent coverage? I think we should start this with HDFS calls since they are notorious in this regarding especially around not timing out. If this is committed and the macro is available, we can find out other problematic blocking calls and cover them too. > For the Java stuff, an alternative approach is to call out via our regular > Thrift-y/JNI-y route to ask Java to get the stack trace using management > beans. I'm pretty sure you can match native thread ids to Java ones, though > based on reading > https://gist.github.com/rednaxelafx/843622/eb0b0877ff4aac77c76e5a50f7621dc32ea451eb > it looks like it's hard. (In jstack, it's the nid=... but you need to do a > hex to decimal conversion for pids. But it looks like it's not readily > available out of Java.) Tried this, but I couldn't find a way to map the nid <-> tid using the API. Thread API in Java does not expose the nid of the thread (which is weird). Of course we could do it the hacky way by parsing the jstack output and extracting the nid field but I don't think that is a reasonable approach. Not sure if you have any other ideas to achieve the same. > I think it may also make sense to expose a counter on how often this happens. > A monitoring tool would want to alert if this is happening a lot, and it > won't want to grep the logs. Even more interesting would be to write down > when it happens on behalf of a query in the profile, but that's not always > possible. Yea, I thought about this. Let me think a bit more and get back to you, flushing out the comments meanwhile. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 4 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 22 Jun 2018 22:26:15 + Gerrit-HasComments: No
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Hello Michael Ho, Lars Volker, Philip Zeyliger, Balazs Jeszenszky, Zoram
Thanga, Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/10696
to look at the new patch set (#4).
Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
..
[DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
This commit adds scoped thread watchdogs around blocking HDFS
IO calls. These dump a user (native + JVM) and kernel stack trace
to the logs if the blocking function call runs for greater than
'threshold' milliseconds. Having such traces will help debug issues
with query hangs due to hangs in external components.
The threshold can be configured using --thread_watchdog_threshold_ms
If stack unwinding tends to be CPU heavy and causing performance
problems, the watchdogs can be disabled by setting
--thread_watchdog_threshold_ms=0 (default = 5000ms)
Usage:
-
This patch adds a macro called SCOPED_WATCHDOG(). Following
is a sample usage:
{
SCOPED_WATCHDOG();
hdfsOpenFile(fs, fname, O_RDONLY, 0, 0, 0)
}
The above code logs kernel and user level stacks for the current thread
if hdfsOpenFile() takes more than 5000 milliseconds.
Sample output:
-
Native Stacks:
==
Injected a manual sleep using SleepForMs() before hdfsOpenFile() to
simulate a hang and the following is logged in the impalad logs.
W0611 16:21:01.602687 347 kernel_stack_watchdog.cc:146] Thread 383
stuck at /home/bharath/Impala/be/src/runtime/io/handle-cache.inline.h:34
for 5036ms:
Kernel stack:
[<>] hrtimer_nanosleep+0xbb/0x180
[<>] SyS_nanosleep+0x66/0x80
[<>] system_call_fastpath+0x1a/0x1f
[<>] 0x
User stack:
@ 0x7f808e7fed40 (unknown)
@ 0x7f808eb9db9d __libc_nanosleep
@ 0x1f460e6 std::this_thread::sleep_for<>()
@ 0x1f44edd impala::SleepForMs()
@ 0x2fef2ca impala::io::HdfsFileHandle::HdfsFileHandle()
@ 0x2fef5f7
impala::io::CachedHdfsFileHandle::CachedHdfsFileHandle()
@ 0x2fefe78 impala::io::FileHandleCache::GetFileHandle()
@ 0x2ff3e3f impala::io::DiskIoMgr::GetCachedHdfsFileHandle()
@ 0x300fad7 impala::io::ScanRange::Read()
@ 0x300bca4 impala::io::ScanRange::DoRead()
@ 0x2ff3207 impala::io::DiskQueue::DiskThreadLoop()
@ 0x2ffac32 boost::_mfi::mf1<>::operator()()
@ 0x2ffa79f boost::_bi::list2<>::operator()<>()
@ 0x2ff9fbd boost::_bi::bind_t<>::operator()()
@ 0x2ff970a
boost::detail::function::void_function_obj_invoker0<>::invoke()
@ 0x1b4e388 boost::function0<>::operator()()
JVM Stack:
Thread not attached to the JVM.
JVM Stacks:
===
If a JVM Thread is attached for a given hung native thread, the the
stack trace output looks like follows.
W0618 20:55:45.93 1220 kernel_stack_watchdog.cc:147] Thread 1381
stuck at be/src/service/impala-server.cc:882 for 5083ms:
Kernel stack:
[<>] futex_wait_queue_me+0xde/0x140
[<>] futex_wait+0x182/0x290
[<>] do_futex+0xde/0x6a0
[<>] SyS_futex+0x71/0x150
[<>] system_call_fastpath+0x1a/0x1f
[<>] 0x
User stack:
@ 0x7fee18315d40 (unknown)
@ 0x7fee186b17ce __pthread_cond_timedwait
@ 0x7fee1b1d6a9f os::PlatformEvent::park()
@ 0x7fee1b1c2c3f ObjectMonitor::wait()
@ 0x7fee1afd5ed2 JVM_MonitorWait
@ 0x7fee03cb6ca4 (unknown)
JVM Stack:
Ljava/lang/Object;wait()
Lorg/apache/impala/catalog/ImpaladCatalog;waitForCatalogUpdate(Line:239)
Lorg/apache/impala/analysis/StmtMetadataLoader;loadTables(Line:136)
Lorg/apache/impala/analysis/StmtMetadataLoader;loadTables(Line:115)
Lorg/apache/impala/service/Frontend;createExecRequest(Line:996)
Lorg/apache/impala/service/JniFrontend;createExecRequest(Line:152)
Change-Id: I28e918761c120043d332b034450208eaf34e3e2b
---
M be/src/common/global-flags.cc
M be/src/exec/hdfs-table-sink.cc
M be/src/kudu/util/debug-util.cc
M be/src/kudu/util/kernel_stack_watchdog.cc
M be/src/runtime/io/handle-cache.inline.h
M be/src/runtime/io/scan-range.cc
M be/src/service/CMakeLists.txt
A be/src/service/jvmti-agent.cc
A be/src/service/jvmti-agent.h
M be/src/util/CMakeLists.txt
A be/src/util/jvm-stack-trace.cc
A be/src/util/jvm-stack-trace.h
A be/src/util/scoped-watchdog.h
M bin/impala-config.sh
14 files changed, 509 insertions(+), 31 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/96/10696/4
--
To view, visit http://gerrit.cloudera.org:8080/10696
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id:
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (9 comments) http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/exec/hdfs-table-sink.cc File be/src/exec/hdfs-table-sink.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/exec/hdfs-table-sink.cc@410 PS3, Line 410: hdfsFileInfo* info = hdfsGetPathInfo(output_partition->hdfs_connection, > This is an RPC too. Should we be watching it? Done http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc File be/src/kudu/util/debug-util.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@62 PS3, Line 62: DEFINE_int32(stack_trace_sig_num, SIGRTMIN, "Signal used by the thread watchdog to " > Why is this configurable? Firstly, these changes in Kudu's util code are expected to be pushed to the Kudu repo and then I plan to cherry-pick them back to Impala to avoid divergence. Now, coming to your question, Kudu uses SIGUSR2 for the signal handler invocation which unfortunately does not work for Impala since JVM already uses it for something else[1]. The idea is to make it configurable in the Kudu code so that Impala can override it. If Kudu project also agrees to use a different signal handler, I suppose we don't need to make it configurable then. [1] https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/signals006.html http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@121 PS3, Line 121: // Stack trace collected from the JVM thread (if one exists). : // TODO: Implement this as a callback rather than polluting Kudu's util code? : impala::JVMStackTrace jstack; > Please apply those changes to Kudu code base if possible. This avoids diver Yep, I need to discuss this with Lars and will try to push as much as I can into Kudu's code base. http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@212 PS3, Line 212:<< "Kudu will not produce thread stack traces."; > s/Kudu/Impala? Will try to make this more generic when I push a Kudu patch for review. Thanks for pointing it out. http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@288 PS3, Line 288: ret << g_comm.jstack.Stringify(); > This is new code. I think it may make sense to feature flag it (--kernel_wa We do have a kill switch for this whole watchdog feature. Do we need to have one specially for the JVM part? http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc File be/src/runtime/io/scan-range.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc@632 PS3, Line 632: fs_, hdfs_file, position_in_file > as mentioned before, we'll want to capture the argument values since that w I plan to fix this in the same patch. Kudu's logging assumes we are only passing filename:line_number (snippet below). lock_guard l(log_lock_); LOG_STRING(WARNING, log_collector_.get()) << "Thread " << p << " stuck at " << frame->status_ << " for " << paused_ms << "ms" << ":\n" << "Kernel stack:\n" << kernel_stack << "\n" << "User stack:\n" << user_stack; } I will send out a consolidated Kudu patch (with all the required Kudu changes from the current patch) and then include this contextual information during rebase (after cherry-picking it onto Impala). http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc@642 PS3, Line 642: current_bytes_read = hdfsRead(fs_, hdfs_file, buffer + *bytes_read, > Isn't this the main thing we're interested in? Done http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt File be/src/service/CMakeLists.txt: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt@53 PS3, Line 53: # Jvmti agent library that registers with the JVM on load. > As I mentioned elsewhere (perhaps later), I'm interested in whether this ad I don't think there is much overhead in the binary size. I'm not sure I understand the rest of your comment. May be can you point some docs to the workaround you are talking about? Without patch: -rwxrwxr-x 1 bharath bharath 380M Jun 22 11:35 libfesupport.so -rwxrwxr-x 1 bharath bharath 376M Jun 22 11:35 impalad -rwxrwxr-x 1 bharath bharath 375M Jun 22 11:36 session-expiry-test -rwxrwxr-x 1 bharath bharath 373M Jun 22 11:36 query-options-test -rwxrwxr-x 1 bharath bharath 372M Jun 22 11:36 hs2-util-test -rw-rw-r-- 1 bharath bharath 71M Jun 22 11:32 libService.a With Patch: -rwxrwxr-x 1 bharath bharath 380M Jun 22 11:24 libfesupport.so -rwxrwxr-x 1 bharath bharath 377M Jun 22 11:24 impalad -rwxrwxr-x 1 bharath bharath 376M Jun 17 09:57 session-expiry-test -rwxrwxr-x 1 bharath bharath 374M
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc File be/src/runtime/io/scan-range.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc@632 PS3, Line 632: fs_, hdfs_file, position_in_file as mentioned before, we'll want to capture the argument values since that will likely be the first question some asks after seeing the callstack. if you don't want to do it in this patch, could you please file a follow on JIRA so we don't forget? -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 22 Jun 2018 16:37:44 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (7 comments) Hi! Thanks for doing this. The big question for me is what our policy is here. Should we be doing this for all blocking system calls? All blocking RPCs? How do we maintain that we have decent coverage? For the Java stuff, an alternative approach is to call out via our regular Thrift-y/JNI-y route to ask Java to get the stack trace using management beans. I'm pretty sure you can match native thread ids to Java ones, though based on reading https://gist.github.com/rednaxelafx/843622/eb0b0877ff4aac77c76e5a50f7621dc32ea451eb it looks like it's hard. (In jstack, it's the nid=... but you need to do a hex to decimal conversion for pids. But it looks like it's not readily available out of Java.) I think it may also make sense to expose a counter on how often this happens. A monitoring tool would want to alert if this is happening a lot, and it won't want to grep the logs. Even more interesting would be to write down when it happens on behalf of a query in the profile, but that's not always possible. http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/exec/hdfs-table-sink.cc File be/src/exec/hdfs-table-sink.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/exec/hdfs-table-sink.cc@410 PS3, Line 410: hdfsFileInfo* info = hdfsGetPathInfo(output_partition->hdfs_connection, This is an RPC too. Should we be watching it? http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc File be/src/kudu/util/debug-util.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@62 PS3, Line 62: DEFINE_int32(stack_trace_sig_num, SIGRTMIN, "Signal used by the thread watchdog to " Why is this configurable? http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@212 PS3, Line 212:<< "Kudu will not produce thread stack traces."; s/Kudu/Impala? http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@288 PS3, Line 288: ret << g_comm.jstack.Stringify(); This is new code. I think it may make sense to feature flag it (--kernel_watchdog_jstack_enabled) so that we can turn it off if we find that it's wrong. http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc File be/src/runtime/io/scan-range.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/runtime/io/scan-range.cc@642 PS3, Line 642: current_bytes_read = hdfsRead(fs_, hdfs_file, buffer + *bytes_read, Isn't this the main thing we're interested in? http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt File be/src/service/CMakeLists.txt: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/service/CMakeLists.txt@53 PS3, Line 53: # Jvmti agent library that registers with the JVM on load. As I mentioned elsewhere (perhaps later), I'm interested in whether this adds a lot to our binary. We're already launching the JVM from a statically linked binary; do we need to point it to another file to get methods? (There's a way around this for normal JNI libraries in JDK1.8+ though I'd have to look it up.) http://gerrit.cloudera.org:8080/#/c/10696/3/bin/impala-config.sh File bin/impala-config.sh: http://gerrit.cloudera.org:8080/#/c/10696/3/bin/impala-config.sh@619 PS3, Line 619: LIBHDFS_OPTS+=" -agentpath:$IMPALA_HOME/be/build/latest/service/libjvmtiagent.so" It surprises me that we have to do this with options, rather than being able to do it directly. What's going on is that we're doubling down here on our reliance on hadoop-hdfs/src/main/native/libhdfs/jni_helper.c. It's definitely not a public API that we should be depending on. Joe ran into https://issues.apache.org/jira/browse/HDFS-12628?jql=reporter%3Djoemcdonnell%20and%20project%3Dhdfs which is somewhat related. It's also problematic that we're introducing a new .so. We shouldn't have to since we statically link things. What's the size of the new .SO? Are we adding 100MB to everyone's builds? impala-config.sh is read in our build process. How do these settings work when we're running on clusters? -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 22 Jun 2018 15:23:48 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc File be/src/kudu/util/debug-util.cc: http://gerrit.cloudera.org:8080/#/c/10696/3/be/src/kudu/util/debug-util.cc@121 PS3, Line 121: // Stack trace collected from the JVM thread (if one exists). : // TODO: Implement this as a callback rather than polluting Kudu's util code? : impala::JVMStackTrace jstack; Please apply those changes to Kudu code base if possible. This avoids divergence between the shared code of Kudu and Impala. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 21 Jun 2018 22:42:37 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/10696/3//COMMIT_MSG Commit Message: http://gerrit.cloudera.org:8080/#/c/10696/3//COMMIT_MSG@20 PS3, Line 20: --thread_watchdog_threshold_ms=0 (default = 5000ms) > I wonder if the default threshold is too low, in the sense that we may get I agree it is too low. It was just meant for testing it easily on my local dev box. 2 mins sounds like a reasonable default to me. Will make that change in the next PS unless there are objections. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 21 Jun 2018 19:56:16 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Zoram Thanga has posted comments on this change. ( http://gerrit.cloudera.org:8080/10696 ) Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/10696/3//COMMIT_MSG Commit Message: http://gerrit.cloudera.org:8080/#/c/10696/3//COMMIT_MSG@20 PS3, Line 20: --thread_watchdog_threshold_ms=0 (default = 5000ms) I wonder if the default threshold is too low, in the sense that we may get a lot of 'false positives' on 'hangs'. The Linux kernel hung task detector has a default timeout of 120 seconds by comparison. -- To view, visit http://gerrit.cloudera.org:8080/10696 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b Gerrit-Change-Number: 10696 Gerrit-PatchSet: 3 Gerrit-Owner: Bharath Vissapragada Gerrit-Reviewer: Balazs Jeszenszky Gerrit-Reviewer: Bharath Vissapragada Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Lars Volker Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 21 Jun 2018 07:00:18 + Gerrit-HasComments: Yes
[Impala-ASF-CR] [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
Bharath Vissapragada has uploaded this change for review. (
http://gerrit.cloudera.org:8080/10696
Change subject: [DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
..
[DRAFT] IMPALA-6189: Add thread watchdogs for HDFS IO calls
This commit adds scoped thread watchdogs around blocking HDFS
IO calls. These dump a user (native + JVM) and kernel stack trace
to the logs if the blocking function call runs for greater than
'threshold' milliseconds. Having such traces will help debug issues
with query hangs due to hangs in external components.
The threshold can be configured using --thread_watchdog_threshold_ms
If stack unwinding tends to be CPU heavy and causing performance
problems, the watchdogs can be disabled by setting
--thread_watchdog_threshold_ms=0 (default = 5000ms)
Usage:
-
This patch adds a macro called SCOPED_WATCHDOG(). Following
is a sample usage:
{
SCOPED_WATCHDOG();
hdfsOpenFile(fs, fname, O_RDONLY, 0, 0, 0)
}
The above code logs kernel and user level stacks for the current thread
if hdfsOpenFile() takes more than 5000 milliseconds.
Sample output:
-
Native Stacks:
==
Injected a manual sleep using SleepForMs() before hdfsOpenFile() to
simulate a hang and the following is logged in the impalad logs.
W0611 16:21:01.602687 347 kernel_stack_watchdog.cc:146] Thread 383
stuck at /home/bharath/Impala/be/src/runtime/io/handle-cache.inline.h:34
for 5036ms:
Kernel stack:
[<>] hrtimer_nanosleep+0xbb/0x180
[<>] SyS_nanosleep+0x66/0x80
[<>] system_call_fastpath+0x1a/0x1f
[<>] 0x
User stack:
@ 0x7f808e7fed40 (unknown)
@ 0x7f808eb9db9d __libc_nanosleep
@ 0x1f460e6 std::this_thread::sleep_for<>()
@ 0x1f44edd impala::SleepForMs()
@ 0x2fef2ca impala::io::HdfsFileHandle::HdfsFileHandle()
@ 0x2fef5f7
impala::io::CachedHdfsFileHandle::CachedHdfsFileHandle()
@ 0x2fefe78 impala::io::FileHandleCache::GetFileHandle()
@ 0x2ff3e3f impala::io::DiskIoMgr::GetCachedHdfsFileHandle()
@ 0x300fad7 impala::io::ScanRange::Read()
@ 0x300bca4 impala::io::ScanRange::DoRead()
@ 0x2ff3207 impala::io::DiskQueue::DiskThreadLoop()
@ 0x2ffac32 boost::_mfi::mf1<>::operator()()
@ 0x2ffa79f boost::_bi::list2<>::operator()<>()
@ 0x2ff9fbd boost::_bi::bind_t<>::operator()()
@ 0x2ff970a
boost::detail::function::void_function_obj_invoker0<>::invoke()
@ 0x1b4e388 boost::function0<>::operator()()
JVM Stack:
Thread not attached to the JVM.
JVM Stacks:
===
If a JVM Thread is attached for a given hung native thread, the the
stack trace output looks like follows.
W0618 20:55:45.93 1220 kernel_stack_watchdog.cc:147] Thread 1381
stuck at be/src/service/impala-server.cc:882 for 5083ms:
Kernel stack:
[<>] futex_wait_queue_me+0xde/0x140
[<>] futex_wait+0x182/0x290
[<>] do_futex+0xde/0x6a0
[<>] SyS_futex+0x71/0x150
[<>] system_call_fastpath+0x1a/0x1f
[<>] 0x
User stack:
@ 0x7fee18315d40 (unknown)
@ 0x7fee186b17ce __pthread_cond_timedwait
@ 0x7fee1b1d6a9f os::PlatformEvent::park()
@ 0x7fee1b1c2c3f ObjectMonitor::wait()
@ 0x7fee1afd5ed2 JVM_MonitorWait
@ 0x7fee03cb6ca4 (unknown)
JVM Stack:
Ljava/lang/Object;wait()
Lorg/apache/impala/catalog/ImpaladCatalog;waitForCatalogUpdate(Line:239)
Lorg/apache/impala/analysis/StmtMetadataLoader;loadTables(Line:136)
Lorg/apache/impala/analysis/StmtMetadataLoader;loadTables(Line:115)
Lorg/apache/impala/service/Frontend;createExecRequest(Line:996)
Lorg/apache/impala/service/JniFrontend;createExecRequest(Line:152)
Change-Id: I28e918761c120043d332b034450208eaf34e3e2b
---
M be/src/common/global-flags.cc
M be/src/exec/hdfs-table-sink.cc
M be/src/kudu/util/debug-util.cc
M be/src/kudu/util/kernel_stack_watchdog.cc
M be/src/runtime/io/handle-cache.inline.h
M be/src/runtime/io/scan-range.cc
M be/src/service/CMakeLists.txt
A be/src/service/jvmti-agent.cc
A be/src/service/jvmti-agent.h
M be/src/util/CMakeLists.txt
A be/src/util/jvm-stack-trace.cc
A be/src/util/jvm-stack-trace.h
A be/src/util/scoped-watchdog.h
M bin/impala-config.sh
14 files changed, 498 insertions(+), 27 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/96/10696/3
--
To view, visit http://gerrit.cloudera.org:8080/10696
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I28e918761c120043d332b034450208eaf34e3e2b
Gerrit-Change-Number: 10696
Gerrit-PatchSet: 3
Gerrit-Owner: Bharath Vissapragada
Gerrit-Reviewer:
