You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@impala.apache.org by "Philip Zeyliger (Code Review)" <ge...@cloudera.org> on 2018/12/27 00:35:05 UTC
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment ids.
Philip Zeyliger has uploaded this change for review. ( http://gerrit.cloudera.org:8080/12129
Change subject: IMPALA-6664: Tag log statements with fragment ids.
......................................................................
IMPALA-6664: Tag log statements with fragment ids.
[Work in progress.]
This is a partial implementation of the desire in IMPALA-6664 to tag all
log statements with their query ids. It re-uses the existing
ThreadDebugInfo infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids, when available.
The fragment id is the query id with the last bits incremented, so
it's possible to correlate a given query.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
The natural follow-up to this would be to tag coordinator threads with
their query id, to capture more log messages that are related to a
query.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
TODO: there's no test here yet...
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
1 file changed, 24 insertions(+), 4 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/1
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 1
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Paul Rogers, Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#6).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info-test.cc
M be/src/common/thread-debug-info.cc
M be/src/common/thread-debug-info.h
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-hs2-server.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M be/src/util/debug-util.h
M lib/python/impala_py_lib/gdb/impala-gdb.py
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
16 files changed, 264 insertions(+), 66 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/6
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 6
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment ids.
Posted by "Zoltan Borok-Nagy (Code Review)" <ge...@cloudera.org>.
Zoltan Borok-Nagy has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment ids.
......................................................................
Patch Set 1: Code-Review+1
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 1
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 02 Jan 2019 14:28:55 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 8: Code-Review+2
Carry +2. I had to make a minor change to the test because the log directory is actually in $IMPALA_EE_LOG_DIR (-ish). Also, functional.alltypes has more partitions/files, so serves as a more reliable test case. The tpcds table I was using was only running on two hosts, so had a bit more trouble.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 8
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 24 Jan 2019 20:17:15 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 4:
(8 comments)
I think I addressed all the comments. Please take another look.
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/common/thread-debug-info.h@a94
PS3, Line 94:
> We should copy parent_.thread_name_, or remove it from struct 'ParentInfo'.
This was a bug (found by unit tests). Fixed.
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
> Yeah, the idea was to make it readable when debugging a minidump or core fi
Cool. I'll take a look at impala-gdb.py and fix it appropriately. Printing out the hex using gdb isn't too bad. I wrote down how to do it in gdb in debug-util.h for lack of a better place.
Unit tests will be fixed in the next iteration.
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node-base.cc
File be/src/exec/hdfs-scan-node-base.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node-base.cc@37
PS3, Line 37: #include "exprs/scalar-expr-evaluator.h"
> nit: do we need this include? Might be better to include it in hdfs-scan-no
Done
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node.cc
File be/src/exec/hdfs-scan-node.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node.cc@325
PS3, Line 325: auto fn = [this, first_thread, scanner_thread_reservation]() {
: this->ScannerThread(first_thread, scanner_thread_reservation);
: };
: std::unique_ptr<Thread> t;
: status = Thread::Create(
> Since we use Thread::Create() later, https://github.com/apache/impala/blob/
No reason to believe it doesn't. I took this from some tracing code that I'm still working on. I tested this manually by adding an extra log message at the beginning of the scanner thread, and can confirm I can see it tagged.
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/runtime/io/disk-io-mgr.cc
File be/src/runtime/io/disk-io-mgr.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/runtime/io/disk-io-mgr.cc@424
PS3, Line 424: // We are now working on behalf of a query, so set thread state appropriately.
: // See also IMPALA-6254 and IMPALA-6417.
: ScopedThreadContext tdi_scope(GetThreadDebugInfo(), worker_context-
> Fyi, IMPALA-6254 and IMPALA-6417 is about to make this automated. Maybe we
Added a comment.
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py
File tests/observability/test_log_fragments.py:
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@23
PS3, Line 23:
> flake8: E302 expected 2 blank lines, found 1
Done
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@26
PS3, Line 26:
> typo:fragments
Done
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@34
PS3, Line 34: """
> nit: result (since it's not a profile, rather an ImpalaBeeswaxResult)
Done
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 4
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 20:01:09 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Tim Armstrong (Code Review)" <ge...@cloudera.org>.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 5: Code-Review+1
Will let ZBN promote to +2
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 5
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 23:54:29 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
Turns out that it's kind of bad that we don't "clear" the contexts reliably. When the threads get re-used you get confusing results for things like "Found local timezone "UTC"". It's fixable with a context wrapper of some sort, so I'll write one of those.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 21:21:37 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 6:
Build Successful
https://jenkins.impala.io/job/gerrit-code-review-checks/1822/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 6
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Fri, 18 Jan 2019 21:08:02 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 7: Verified-1
Build failed: https://jenkins.impala.io/job/gerrit-verify-dryrun/3660/
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 7
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 23 Jan 2019 01:23:31 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Paul Rogers, Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#8).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info-test.cc
M be/src/common/thread-debug-info.cc
M be/src/common/thread-debug-info.h
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-hs2-server.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M be/src/util/debug-util.h
M lib/python/impala_py_lib/gdb/impala-gdb.py
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
16 files changed, 264 insertions(+), 66 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/8
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 8
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 8:
Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/3671/ DRY_RUN=false
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 8
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 24 Jan 2019 20:17:25 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Reviewed-on: http://gerrit.cloudera.org:8080/12129
Reviewed-by: Philip Zeyliger <ph...@cloudera.com>
Tested-by: Impala Public Jenkins <im...@cloudera.com>
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info-test.cc
M be/src/common/thread-debug-info.cc
M be/src/common/thread-debug-info.h
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-hs2-server.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M be/src/util/debug-util.h
M lib/python/impala_py_lib/gdb/impala-gdb.py
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
16 files changed, 264 insertions(+), 66 deletions(-)
Approvals:
Philip Zeyliger: Looks good to me, approved
Impala Public Jenkins: Verified
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 9
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Zoltan Borok-Nagy (Code Review)" <ge...@cloudera.org>.
Zoltan Borok-Nagy has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 5:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
> Cool. I'll take a look at impala-gdb.py and fix it appropriately. Printing
Thanks! Do you plan to fix it in this change, or in a follow-up commit?
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-hs2-server.cc
File be/src/service/impala-hs2-server.cc:
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-hs2-server.cc@126
PS5, Line 126: ScopedThreadContext(GetThreadDebugInfo(), query_ctx.query_id);
Currently it creates a temporary object that is deleted promptly.
You need to create a variable so the TDI object only gets reset at the end of the function.
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-internal-service.cc
File be/src/service/impala-internal-service.cc:
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-internal-service.cc@49
PS5, Line 49: ScopedThreadContext(GetThreadDebugInfo(), params.query_ctx.query_id);
It creates a temporary that is deleted promptly.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 5
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Fri, 18 Jan 2019 13:48:41 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 4:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12129/4/tests/observability/test_log_fragments.py
File tests/observability/test_log_fragments.py:
http://gerrit.cloudera.org:8080/#/c/12129/4/tests/observability/test_log_fragments.py@57
PS4, Line 57: e
> flake8: E722 do not use bare except'
Done
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 4
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 20:46:44 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 2:
(7 comments)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc
File be/src/common/logging.cc:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@55
PS2, Line 55: kZeroUniqueId
> ZERO_UNIQUE_ID
Done
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@63
PS2, Line 63: if (id == kZeroUniqueId) {
> nit: one line
Done
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@67
PS2, Line 67: if (changed != nullptr) {
> nit: one line
Done
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
> I think there was some reason this was a human-readable string - maybe to m
Yep, I'll wait for Zoltan's input.
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@118
PS2, Line 118: TUniqueId query_id_;
> Can you document that these are 0 if this thread isn't part of a query or i
Done
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h
File be/src/runtime/io/request-context.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h@403
PS2, Line 403: TUniqueId instance_id_;
> Can you document that these are 0 if we're not working on behalf of a query
I didn't do this because I don't think a request-context could be working not on behalf of a query. Happy to comment anyway. Do you think i should set this in RegisterContext() rather than around it?
http://gerrit.cloudera.org:8080/#/c/12129/2/tests/common/impala_test_suite.py
File tests/common/impala_test_suite.py:
http://gerrit.cloudera.org:8080/#/c/12129/2/tests/common/impala_test_suite.py@843
PS2, Line 843: def assert_impalad_log_contains(self, level, line_regex, expected_count=1):
> I don't see anything using this.
d'oh; forgot to add the test file.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:49:54 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Tim Armstrong (Code Review)" <ge...@cloudera.org>.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h
File be/src/runtime/io/request-context.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h@403
PS2, Line 403: TUniqueId instance_id_;
> I didn't do this because I don't think a request-context could be working n
Yeah that is true.
I think if it's an invariant that they're always set we should just pass them in via RegisterContext/the constructor.
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py
File tests/observability/test_log_fragments.py:
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@26
PS3, Line 26: def test_log_framgnets(self):
typo:fragments
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@34
PS3, Line 34: profile
nit: result (since it's not a profile, rather an ImpalaBeeswaxResult)
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:59:33 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 2:
(4 comments)
Please take another look!
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc
File be/src/common/logging.cc:
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@55
PS1, Line 55: const TUniqueId kZeroUniqueId;
> Nice. I think the next step would be to (re)define VLOG_QUERY or something like it, that would be called for debug logging in the query/FINST lifecycle code?
With the updated change, this is pretty much done. There may be threads (like krpc sender) that don't know or haven't annotated what query they're working on, but this captures a good chunk of it.
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@55
PS1, Line 55: Uniqu
> std:: not needed
Done
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@65
PS1, Line 65: }
> The API chosen is a little unfortunate since it requires reallocating 's' t
Indeed. Todd probably says we should use async_logger. If we have an opinion on that, that would be a good opportunity to figure out if we want to make this interface better. In practice, though, we've not seen this show up in profiling, so I'm ignoring it for now.
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@68
PS1, Line 68: ue;
> same here
Done
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:10:47 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 7: Code-Review+2
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 7
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 22 Jan 2019 20:47:12 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Zoltan Borok-Nagy (Code Review)" <ge...@cloudera.org>.
Zoltan Borok-Nagy has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 6: Code-Review+2
Thanks for applying the changes!
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 6
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Mon, 21 Jan 2019 10:54:41 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py
File tests/observability/test_log_fragments.py:
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@23
PS3, Line 23: class TestLogFragments(ImpalaTestSuite):
flake8: E302 expected 2 blank lines, found 1
http://gerrit.cloudera.org:8080/#/c/12129/3/tests/observability/test_log_fragments.py@44
PS3, Line 44: e
flake8: E501 line too long (94 > 90 characters)
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:51:44 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Zoltan Borok-Nagy (Code Review)" <ge...@cloudera.org>.
Zoltan Borok-Nagy has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 2:
(5 comments)
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/common/thread-debug-info.h@a94
PS3, Line 94:
We should copy parent_.thread_name_, or remove it from struct 'ParentInfo'.
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
> Yep, I'll wait for Zoltan's input.
Yeah, the idea was to make it readable when debugging a minidump or core file and you can't invoke PrintId() from GDB.
But since PrintId() just prints the hex of members 'hi' and 'lo', it should be fine.
But we also need to update 'lib/python/impala_py_lib/gdb/impala-gdb.py' because currently it expects 'instance_id_' to be a string.
It also breaks the unit tests in 'thread-debug-info-test.cc'.
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node-base.cc
File be/src/exec/hdfs-scan-node-base.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node-base.cc@37
PS3, Line 37: #include "common/thread-debug-info.h"
nit: do we need this include? Might be better to include it in hdfs-scan-node.cc
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node.cc
File be/src/exec/hdfs-scan-node.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/exec/hdfs-scan-node.cc@325
PS3, Line 325: ThreadDebugInfo* parent_thread_debug_info = GetThreadDebugInfo();
: DCHECK(parent_thread_debug_info != nullptr);
: auto fn = [this, first_thread, scanner_thread_reservation,
: parent_thread_debug_info]() {
: GetThreadDebugInfo()->SetParentInfo(parent_thread_debug_info);
Since we use Thread::Create() later, https://github.com/apache/impala/blob/274e96bd147b5d91872c441c3a600fa8d5295bbe/be/src/util/thread.cc#L317 and https://github.com/apache/impala/blob/274e96bd147b5d91872c441c3a600fa8d5295bbe/be/src/util/thread.cc#L351 should do this automatically.
Doesn't it happen?
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/runtime/io/disk-io-mgr.cc
File be/src/runtime/io/disk-io-mgr.cc:
http://gerrit.cloudera.org:8080/#/c/12129/3/be/src/runtime/io/disk-io-mgr.cc@424
PS3, Line 424: // We are now working on behalf of a query, so set thread state appropriately.
: GetThreadDebugInfo()->SetQueryId(worker_context->query_id());
: GetThreadDebugInfo()->SetInstanceId(worker_context->instance_id());
Fyi, IMPALA-6254 and IMPALA-6417 is about to make this automated. Maybe we could add a TODO here and mention those Jiras.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 09 Jan 2019 11:25:26 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 5:
Build Successful
https://jenkins.impala.io/job/gerrit-code-review-checks/1804/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 5
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 21:11:36 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Paul Rogers (Code Review)" <ge...@cloudera.org>.
Paul Rogers has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
Does/should this fix up the Java side messages as well? May be some configuration in Log4J that produces a result similar to what you've achieved on the C++ side.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 09 Jan 2019 06:47:17 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#2).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info.h
M be/src/exec/hdfs-scan-node-base.cc
M be/src/exec/hdfs-scan-node.cc
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
11 files changed, 118 insertions(+), 53 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/2
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment ids.
......................................................................
Patch Set 1:
Build Successful
https://jenkins.impala.io/job/gerrit-code-review-checks/1674/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 1
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 27 Dec 2018 01:06:58 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 8: Verified+1
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 8
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Fri, 25 Jan 2019 00:47:08 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 8:
Build Successful
https://jenkins.impala.io/job/gerrit-code-review-checks/1877/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 8
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 24 Jan 2019 21:23:08 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#3).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info.h
M be/src/exec/hdfs-scan-node-base.cc
M be/src/exec/hdfs-scan-node.cc
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
12 files changed, 160 insertions(+), 53 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/3
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 4:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12129/4/tests/observability/test_log_fragments.py
File tests/observability/test_log_fragments.py:
http://gerrit.cloudera.org:8080/#/c/12129/4/tests/observability/test_log_fragments.py@57
PS4, Line 57: e
flake8: E722 do not use bare except'
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 4
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 20:01:54 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Paul Rogers, Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#5).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info-test.cc
M be/src/common/thread-debug-info.cc
M be/src/common/thread-debug-info.h
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-hs2-server.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M be/src/util/debug-util.h
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
15 files changed, 260 insertions(+), 64 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/5
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 5
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment ids.
Posted by "Zoram Thanga (Code Review)" <ge...@cloudera.org>.
Zoram Thanga has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment ids.
......................................................................
Patch Set 1: Code-Review+1
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc
File be/src/common/logging.cc:
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@55
PS1, Line 55: void PrependFragment(std::string* s, bool* changed) {
Nice. I think the next step would be to (re)define VLOG_QUERY or something like it, that would be called for debug logging in the query/FINST lifecycle code?
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 1
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 02 Jan 2019 17:52:32 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 5:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
> Thanks! Do you plan to fix it in this change, or in a follow-up commit?
Thanks for catching that I didn't do this. I fixed it. Turned out to be nice and easy.
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-hs2-server.cc
File be/src/service/impala-hs2-server.cc:
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-hs2-server.cc@126
PS5, Line 126: ScopedThreadContext(GetThreadDebugInfo(), query_ctx.query_id);
> Currently it creates a temporary object that is deleted promptly.
Whoops. Thanks for catching this. Done.
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-internal-service.cc
File be/src/service/impala-internal-service.cc:
http://gerrit.cloudera.org:8080/#/c/12129/5/be/src/service/impala-internal-service.cc@49
PS5, Line 49: ScopedThreadContext(GetThreadDebugInfo(), params.query_ctx.query_id);
> It creates a temporary that is deleted promptly.
Done
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 5
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 22 Jan 2019 20:46:54 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
> Does/should this fix up the Java side messages as well? May be some
> configuration in Log4J that produces a result similar to what
> you've achieved on the C++ side.
The Java side of Impala logs to Glog via fe/src/main/java/org/apache/impala/util/GlogAppender.java which does JNI to write to GLOG. As a bonus, the log line below is an example of how we get this tagging for free assuming that the Java code isn't creating threads and so on. For the planner, it's single-threaded as far as I know, so we don't have to do anything special.
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Wed, 09 Jan 2019 19:18:56 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 2:
Build Failed
https://jenkins.impala.io/job/gerrit-code-review-checks/1739/ : Initial code review checks failed. See linked job for details on the failure.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:40:14 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 3:
Build Failed
https://jenkins.impala.io/job/gerrit-code-review-checks/1740/ : Initial code review checks failed. See linked job for details on the failure.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 3
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 20:20:35 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Philip Zeyliger (Code Review)" <ge...@cloudera.org>.
Hello Paul Rogers, Zoltan Borok-Nagy, Zoram Thanga, Tim Armstrong, Impala Public Jenkins,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12129
to look at the new patch set (#4).
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
IMPALA-6664: Tag log statements with fragment or query ids.
This implements much of the desire in IMPALA-6664 to tag all log
statements with their query ids. It re-uses the existing ThreadDebugInfo
infrastructure as well as the existing
InstallLogMessageListenerFunction() patch to glog (currently used for
log redaction) to prefix log messages with fragment ids or query ids,
when available. The fragment id is the query id with the last bits
incremented, so it's possible to correlate a given query's log messages.
For example:
$ grep 85420d575b9ff4b9:402b8868 logs/cluster/impalad.INFO
I0108 10:39:16.453958 14752 impala-server.cc:1052] 85420d575b9ff4b9:402b886800000000] Registered query query_id=85420d575b9ff4b9:402b886800000000 session_id=aa45e480434f0516:101ae5ac12679d94
I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b886800000000] Analyzing query: select count(*) from tpcds.web_sales
I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b886800000000] Analysis finished.
I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b886800000000] Schedule for id=85420d575b9ff4b9:402b886800000000 in pool_name=default-pool per_host_mem_estimate=180.02 MB PoolConfig: max_requests=-1 max_queued=200 max_mem=-1.00 B
I0108 10:39:16.463603 14818 admission-controller.cc:603] 85420d575b9ff4b9:402b886800000000] Stats: agg_num_running=0, agg_num_queued=0, agg_mem_reserved=0, local_host(local_mem_admitted=0, num_admitted_running=0, num_queued=0, backend_mem_reserved=0)
I0108 10:39:16.463780 14818 admission-controller.cc:635] 85420d575b9ff4b9:402b886800000000] Admitted query id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b886800000000] Exec() query_id=85420d575b9ff4b9:402b886800000000 stmt=select count(*) from tpcds.web_sales
I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b886800000000] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b886800000000 coord=pannier.sf.cloudera.com:22000 #instances=2
I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b886800000000] started execution on 2 backends for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b886800000000] Executing instance. instance_id=85420d575b9ff4b9:402b886800000000 fragment_idx=0 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=1
I0108 10:39:16.467627 14824 query-state.cc:579] 85420d575b9ff4b9:402b886800000001] Executing instance. instance_id=85420d575b9ff4b9:402b886800000001 fragment_idx=1 per_fragment_instance_idx=0 coord_state_idx=0 #in-flight=2
I0108 10:39:16.820933 14824 query-state.cc:587] 85420d575b9ff4b9:402b886800000001] Instance completed. instance_id=85420d575b9ff4b9:402b886800000001 #in-flight=1 status=OK
I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b886800000000] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b886800000000, node=2
I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b886800000000: first in-progress backend: pannier.sf.cloudera.com:22000
I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b886800000000] get_results_metadata(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b886800000000] ExecState: query id=85420d575b9ff4b9:402b886800000000 execution completed
I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b886800000000] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b886800000000] Instance completed. instance_id=85420d575b9ff4b9:402b886800000000 #in-flight=0 status=OK
I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b886800000000] Release admission control resources for query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.174837 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000001
I0108 10:39:17.174856 14821 krpc-data-stream-mgr.cc:325] cancelling all streams for fragment_instance_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179621 14752 impala-beeswax-server.cc:239] 85420d575b9ff4b9:402b886800000000] close(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179651 14752 impala-server.cc:1131] 85420d575b9ff4b9:402b886800000000] UnregisterQuery(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179666 14752 impala-server.cc:1238] 85420d575b9ff4b9:402b886800000000] Cancel(): query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:17.179814 14752 coordinator.cc:684] 85420d575b9ff4b9:402b886800000000] CancelBackends() query_id=85420d575b9ff4b9:402b886800000000, tried to cancel 0 backends
I0108 10:39:17.203898 14752 query-exec-mgr.cc:184] 85420d575b9ff4b9:402b886800000000] ReleaseQueryState(): deleted query_id=85420d575b9ff4b9:402b886800000000
I0108 10:39:18.108947 14752 impala-server.cc:1993] 85420d575b9ff4b9:402b886800000000] Connection from client ::ffff:172.16.35.186:52096 closed, closing 1 associated session(s)
I0108 10:39:18.108996 14752 impala-server.cc:1249] 85420d575b9ff4b9:402b886800000000] Closing session: aa45e480434f0516:101ae5ac12679d94
I0108 10:39:18.109035 14752 impala-server.cc:1291] 85420d575b9ff4b9:402b886800000000] Closed session: aa45e480434f0516:101ae5ac12679d94
There are a few caveats here: the thread state isn't "scoped", so the "Closing
session" log statement is technically not part of the query. When that thread
is re-used for another query, it corrects itself. Some threads, like 14821,
aren't using the thread locals. In some case, we should go back and
add GetThreadDebugInfo()->SetQueryId(...) statements.
I've used this to debug some crashes (of my own doing) while running
parallel tests, and it's been quite helpful.
An alternative would be to use Kudu's be/src/kudu/util/async_logger.h,
and add the "Listener" functionality to it directly. Another alternative
would be to re-write all the *LOG macros, but this is quite painful (and
presumably was rejected when log redaction was introduced).
I changed thread-debug-info to capture TUniqueId (a thrift struct with
two int64s) rather than the string representation. This made it easier
to compare with the "0:0" id, which we treat as "unset". If a developer
needs to analyze it from a debugger, gdb can print out hex just fine.
I added some context to request-context to be able to pipe ids through
to disk IO threads as well.
To test this, I moved "assert_log_contains" up to impala_test_suite, and
had it handle the default log location case. The test needs a sleep for
log buffering, but, it seems like a test with a sleep running in
parallel is better than a custom cluster test, which reboots the cluster
(and loads metadata).
Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
---
M be/src/common/logging.cc
M be/src/common/thread-debug-info-test.cc
M be/src/common/thread-debug-info.cc
M be/src/common/thread-debug-info.h
M be/src/runtime/io/disk-io-mgr.cc
M be/src/runtime/io/request-context.cc
M be/src/runtime/io/request-context.h
M be/src/runtime/query-state.cc
M be/src/service/impala-hs2-server.cc
M be/src/service/impala-internal-service.cc
M be/src/service/impala-server.cc
M be/src/util/debug-util.h
M tests/common/custom_cluster_test_suite.py
M tests/common/impala_test_suite.py
A tests/observability/test_log_fragments.py
15 files changed, 260 insertions(+), 64 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/29/12129/4
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 4
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 4:
Build Successful
https://jenkins.impala.io/job/gerrit-code-review-checks/1800/ : Initial code review checks passed. Use gerrit-verify-dryrun-external or gerrit-verify-dryrun to run full precommit tests.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 4
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 17 Jan 2019 20:37:01 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 7:
Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/3660/ DRY_RUN=false
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 7
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Paul Rogers <pr...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 22 Jan 2019 20:47:13 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
Posted by "Tim Armstrong (Code Review)" <ge...@cloudera.org>.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment or query ids.
......................................................................
Patch Set 2:
(7 comments)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc
File be/src/common/logging.cc:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@55
PS2, Line 55: kZeroUniqueId
ZERO_UNIQUE_ID
(This is a difference from the google C++ style for better or worse: https://cwiki.apache.org/confluence/pages/viewpage.action?pageId=65868536)
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@63
PS2, Line 63: if (id == kZeroUniqueId) {
nit: one line
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/logging.cc@67
PS2, Line 67: if (changed != nullptr) {
nit: one line
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h
File be/src/common/thread-debug-info.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@a116
PS2, Line 116:
I think there was some reason this was a human-readable string - maybe to make it more readable if we printed in the minidump handler? Zoltan probably remembers. Anyway, this seems OK too.
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/common/thread-debug-info.h@118
PS2, Line 118: TUniqueId query_id_;
Can you document that these are 0 if this thread isn't part of a query or instanc?
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h
File be/src/runtime/io/request-context.h:
http://gerrit.cloudera.org:8080/#/c/12129/2/be/src/runtime/io/request-context.h@403
PS2, Line 403: TUniqueId instance_id_;
Can you document that these are 0 if we're not working on behalf of a query?
http://gerrit.cloudera.org:8080/#/c/12129/2/tests/common/impala_test_suite.py
File tests/common/impala_test_suite.py:
http://gerrit.cloudera.org:8080/#/c/12129/2/tests/common/impala_test_suite.py@843
PS2, Line 843: def assert_impalad_log_contains(self, level, line_regex, expected_count=1):
I don't see anything using this.
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Tue, 08 Jan 2019 19:34:01 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment ids.
Posted by "Tim Armstrong (Code Review)" <ge...@cloudera.org>.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12129 )
Change subject: IMPALA-6664: Tag log statements with fragment ids.
......................................................................
Patch Set 1:
(5 comments)
http://gerrit.cloudera.org:8080/#/c/12129/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/12129/1//COMMIT_MSG@31
PS1, Line 31: TODO: there's no test here yet...
I'll wait for this before +2ing.
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc
File be/src/common/logging.cc:
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@55
PS1, Line 55: std::
std:: not needed
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@59
PS1, Line 59: if (changed != nullptr) {
It seems reasonable to assume that 'changed' is non-NULL.
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@65
PS1, Line 65: // Manipulates log messages by:
The API chosen is a little unfortunate since it requires reallocating 's' to prepend anything. Looking at the glog patch, it wouldn't be that hard to provide an alternative way to return a prefix.
I guess the overhead probably isn't enough to worry about, and it looks like the inefficiencies in the glog patch haven't shown up in any profiling, it just offends my sensibilities a bit :).
http://gerrit.cloudera.org:8080/#/c/12129/1/be/src/common/logging.cc@68
PS1, Line 68: std:
same here
--
To view, visit http://gerrit.cloudera.org:8080/12129
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I6634ef9d1a7346339f24f2d40a7a3aa36a535da8
Gerrit-Change-Number: 12129
Gerrit-PatchSet: 1
Gerrit-Owner: Philip Zeyliger <ph...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins <im...@cloudera.com>
Gerrit-Reviewer: Tim Armstrong <ta...@cloudera.com>
Gerrit-Reviewer: Zoltan Borok-Nagy <bo...@cloudera.com>
Gerrit-Reviewer: Zoram Thanga <zo...@cloudera.com>
Gerrit-Comment-Date: Thu, 03 Jan 2019 17:56:51 +0000
Gerrit-HasComments: Yes