[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 25 Jan 2019 00:47:08 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174815 14821 query-state.cc:604] Cancel: qu
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 24 Jan 2019 21:23:08 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 24 Jan 2019 20:17:15 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 24 Jan 2019 20:17:25 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Wed, 23 Jan 2019 01:23:31 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 22 Jan 2019 20:47:12 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 22 Jan 2019 20:46:54 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 22 Jan 2019 20:47:13 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Mon, 21 Jan 2019 10:54:41 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 18 Jan 2019 21:08:02 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Fri, 18 Jan 2019 13:48:41 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 23:54:29 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 21:11:36 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 20:46:44 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 20:37:01 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 20:01:54 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Thu, 17 Jan 2019 20:01:09 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] 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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Wed, 09 Jan 2019 19:18:56 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Wed, 09 Jan 2019 11:25:26 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Paul Rogers Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Wed, 09 Jan 2019 06:47:17 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 21:21:37 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 20:20:35 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:59:33 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:51:44 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:49:54 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources for query_id
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:40:14 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:34:01 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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:402b8868] Registered query query_id=85420d575b9ff4b9:402b8868 session_id=aa45e480434f0516:101ae5ac12679d94 I0108 10:39:16.454738 14752 Frontend.java:1242] 85420d575b9ff4b9:402b8868] Analyzing query: select count(*) from tpcds.web_sales I0108 10:39:16.456627 14752 Frontend.java:1282] 85420d575b9ff4b9:402b8868] Analysis finished. I0108 10:39:16.463538 14818 admission-controller.cc:598] 85420d575b9ff4b9:402b8868] Schedule for id=85420d575b9ff4b9:402b8868 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:402b8868] 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:402b8868] Admitted query id=85420d575b9ff4b9:402b8868 I0108 10:39:16.463896 14818 coordinator.cc:93] 85420d575b9ff4b9:402b8868] Exec() query_id=85420d575b9ff4b9:402b8868 stmt=select count(*) from tpcds.web_sales I0108 10:39:16.464795 14818 coordinator.cc:356] 85420d575b9ff4b9:402b8868] starting execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.466384 24891 impala-internal-service.cc:49] ExecQueryFInstances(): query_id=85420d575b9ff4b9:402b8868 coord=pannier.sf.cloudera.com:22000 #instances=2 I0108 10:39:16.467339 14818 coordinator.cc:370] 85420d575b9ff4b9:402b8868] started execution on 2 backends for query_id=85420d575b9ff4b9:402b8868 I0108 10:39:16.467536 14823 query-state.cc:579] 85420d575b9ff4b9:402b8868] Executing instance. instance_id=85420d575b9ff4b9:402b8868 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:402b88680001] Executing instance. instance_id=85420d575b9ff4b9:402b88680001 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:402b88680001] Instance completed. instance_id=85420d575b9ff4b9:402b88680001 #in-flight=1 status=OK I0108 10:39:17.122299 14823 krpc-data-stream-mgr.cc:294] 85420d575b9ff4b9:402b8868] DeregisterRecvr(): fragment_instance_id=85420d575b9ff4b9:402b8868, node=2 I0108 10:39:17.123500 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22001 remaining=2 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.123509 24038 coordinator-backend-state.cc:265] query_id=85420d575b9ff4b9:402b8868: first in-progress backend: pannier.sf.cloudera.com:22000 I0108 10:39:17.167752 14752 impala-beeswax-server.cc:197] 85420d575b9ff4b9:402b8868] get_results_metadata(): query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168762 14752 coordinator.cc:483] 85420d575b9ff4b9:402b8868] ExecState: query id=85420d575b9ff4b9:402b8868 execution completed I0108 10:39:17.168808 14752 coordinator.cc:608] 85420d575b9ff4b9:402b8868] Coordinator waiting for backends to finish, 1 remaining. query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.168880 14823 query-state.cc:587] 85420d575b9ff4b9:402b8868] Instance completed. instance_id=85420d575b9ff4b9:402b8868 #in-flight=0 status=OK I0108 10:39:17.168977 14821 query-state.cc:252] UpdateBackendExecState(): last report for 85420d575b9ff4b9:402b8868 I0108 10:39:17.174401 24038 coordinator.cc:709] Backend completed: host=pannier.sf.cloudera.com:22000 remaining=1 query_id=85420d575b9ff4b9:402b8868 I0108 10:39:17.174513 14752 coordinator.cc:814] 85420d575b9ff4b9:402b8868] Release admission control resources for query_id
[Impala-ASF-CR] IMPALA-6664: Tag log statements with fragment or query ids.
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 Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Reviewer: Zoltan Borok-Nagy Gerrit-Reviewer: Zoram Thanga Gerrit-Comment-Date: Tue, 08 Jan 2019 19:10:47 + Gerrit-HasComments: Yes