[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Impala Public Jenkins has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. IMPALA-5940: Avoid log spew by using Status::Expected() This change converts two more callers of Status() to Status::Expected() to avoid log spew and the overhead of stack crawling. These two call sites can easily fill the log when there is any network issue. Testing done: Ran concurrent TPC-DS workload with 256 users and verified the log spew is not there. Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Reviewed-on: http://gerrit.cloudera.org:8080/8255 Reviewed-by: Michael HoTested-by: Impala Public Jenkins --- M be/src/rpc/thrift-client.cc M be/src/service/impala-server.cc 2 files changed, 9 insertions(+), 4 deletions(-) Approvals: Michael Ho: Looks good to me, approved Impala Public Jenkins: Verified -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: merged Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 4 Gerrit-Owner: Michael Ho Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 3: Verified+1 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 3 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Thu, 12 Oct 2017 01:34:12 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 3: Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/1332/ -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 3 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 21:34:25 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 3: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 3 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 21:18:00 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Hello Sailesh Mukil, Dan Hecht, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8255 to look at the new patch set (#3). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. IMPALA-5940: Avoid log spew by using Status::Expected() This change converts two more callers of Status() to Status::Expected() to avoid log spew and the overhead of stack crawling. These two call sites can easily fill the log when there is any network issue. Testing done: Ran concurrent TPC-DS workload with 256 users and verified the log spew is not there. Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 --- M be/src/rpc/thrift-client.cc M be/src/service/impala-server.cc 2 files changed, 9 insertions(+), 4 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/55/8255/3 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 3 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 2: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 2 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 19:08:01 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 2: (1 comment) http://gerrit.cloudera.org:8080/#/c/8255/2/be/src/rpc/thrift-client.cc File be/src/rpc/thrift-client.cc: http://gerrit.cloudera.org:8080/#/c/8255/2/be/src/rpc/thrift-client.cc@74 PS2, Line 74: are typo: aren't -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 2 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 19:00:06 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 1: (2 comments) http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/rpc/thrift-client.cc File be/src/rpc/thrift-client.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/rpc/thrift-client.cc@71 PS1, Line 71: } > I think we should make it clear why we use Expected() when we do (since we Done http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc File be/src/service/impala-server.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc@1173 PS1, Line 1173: INTERNAL_ERROR > hmm, if this is expected (as the comment claims), then this shouldn't be an Fixed. Was just preserving the previous logic. -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 18:59:26 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Hello Sailesh Mukil, Dan Hecht, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8255 to look at the new patch set (#2). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. IMPALA-5940: Avoid log spew by using Status::Expected() This change converts two more callers of Status() to Status::Expected() to avoid log spew and the overhead of stack crawling. These two call sites can easily fill the log when there is any network issue. Testing done: Ran concurrent TPC-DS workload with 256 users and verified the log spew is not there. Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 --- M be/src/rpc/thrift-client.cc M be/src/service/impala-server.cc 2 files changed, 9 insertions(+), 4 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/55/8255/2 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 2 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 1: (2 comments) http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/rpc/thrift-client.cc File be/src/rpc/thrift-client.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/rpc/thrift-client.cc@71 PS1, Line 71: } I think we should make it clear why we use Expected() when we do (since we don't want to normally use it). So how about a quick comment about that explaining under what condition this error is expected. http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc File be/src/service/impala-server.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc@1173 PS1, Line 1173: INTERNAL_ERROR hmm, if this is expected (as the comment claims), then this shouldn't be an INTERNAL_ERROR. INTERNAL_ERROR means we've hit a bug of some sort (i.e. some invariant was violated). That's not this case. Anyway, you don't have to fix that now if you don't want. -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael HoGerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 17:39:36 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Sailesh Mukil has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 1: Code-Review+1 (1 comment) http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc File be/src/service/impala-server.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc@1170 PS1, Line 1170: const string& err = Substitute("ReportExecStatus(): Received report for unknown " > Actually, we are still printing this line (see line 1172) below. We are jus Ah ok, got confused. I incorrectly thought it was printing to a higher log level that's not enabled by default. -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael HoGerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 06:04:11 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 1: (1 comment) http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc File be/src/service/impala-server.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc@1170 PS1, Line 1170: const string& err = Substitute("ReportExecStatus(): Received report for unknown " > I find this to be a useful log when debugging user issues. It lets me know Actually, we are still printing this line (see line 1172) below. We are just not printing the stack trace. -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael HoGerrit-Reviewer: Michael Ho Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 05:54:25 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Sailesh Mukil has posted comments on this change. ( http://gerrit.cloudera.org:8080/8255 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. Patch Set 1: (1 comment) http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc File be/src/service/impala-server.cc: http://gerrit.cloudera.org:8080/#/c/8255/1/be/src/service/impala-server.cc@1170 PS1, Line 1170: const string& err = Substitute("ReportExecStatus(): Received report for unknown " I find this to be a useful log when debugging user issues. It lets me know if there were late RPCs and in some cases if some fragment instances outlived the coordinator. But I agree that this is a lot of noise if printed more than once. Maybe the effect of this log will be assuaged by IMPALA-4063? -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael HoGerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 11 Oct 2017 05:17:00 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()
Michael Ho has uploaded this change for review. ( http://gerrit.cloudera.org:8080/8255 Change subject: IMPALA-5940: Avoid log spew by using Status::Expected() .. IMPALA-5940: Avoid log spew by using Status::Expected() This change converts two more callers of Status() to Status::Expected() to avoid log spew and the overhead of stack crawling. These two call sites can easily fill the log when there is any network issue. Testing done: Ran concurrent TPC-DS workload with 256 users and verified the log spew is not there. Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 --- M be/src/rpc/thrift-client.cc M be/src/service/impala-server.cc 2 files changed, 6 insertions(+), 4 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/55/8255/1 -- To view, visit http://gerrit.cloudera.org:8080/8255 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newchange Gerrit-Change-Id: I87493394074a7fdb4e912f4ab2436dd7050d45b3 Gerrit-Change-Number: 8255 Gerrit-PatchSet: 1 Gerrit-Owner: Michael Ho
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Impala Public Jenkins has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. IMPALA-5940: Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. The following messages will no longer log: "Failed to codegen MaterializeTuple() due to unsupported type: $0" "Not implemented for this format." "ScalarFnCall Codegen not supported for CHAR" "Could not codegen CodegenMaterializeExprs: " "Could not codegen TupleRowComparator::Compare(): $0" These codegen related messages were happening at every execution node, and were therefore very common. In addition, the following messages, which were very frequent in the logs, now will log, but without the back trace: "Query Id ... not found." To do this, I changed them from logging implicitly via Status(...) to logging explicitly. I have not fixed this message: "... Client ... timed-out during recv call." It's in DoRpc(), and not all callers of DoRpc() have independent logging. For now, we'll trade a little bit of log spam for clearer debugging. The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. * Manual testing for one of the new back-trace-suppressed paths: $ impala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:21000 GetRuntimeProfile 'beeswaxd.ttypes.QueryHandle()' Traceback (most recent call last): File "shell/gen-py/ImpalaService/ImpalaService-remote", line 106, in pp.pprint(client.GetRuntimeProfile(eval(args[0]),)) File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 161, in GetRuntimeProfile return self.recv_GetRuntimeProfile() File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 184, in recv_GetRuntimeProfile raise result.error beeswaxd.ttypes.BeeswaxException: BeeswaxException(handle=QueryHandle(log_context='', id=''), log_context='', SQLState='HY000', _message='GetRuntimeProfile error: Query id 0:0 not found.\n', errorCode=0) $ grep 'Query id' logs/cluster/impalad.INFO | tail -n 1 I0926 20:29:09.44 6787 impala-server.cc:642] Query id 0:0 not found. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Reviewed-on: http://gerrit.cloudera.org:8080/8100 Reviewed-by: Tim ArmstrongTested-by: Impala Public Jenkins --- M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/tuple.cc M be/src/service/impala-server.cc M be/src/util/tuple-row-compare.cc 6 files changed, 16 insertions(+), 15 deletions(-) Approvals: Tim Armstrong: Looks good to me, approved Impala Public Jenkins: Verified -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: merged Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 9 Gerrit-Owner: Philip Zeyliger Gerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Reviewer: Tim Armstrong
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 8: Verified+1 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 8 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Reviewer: Tim Armstrong Gerrit-Comment-Date: Tue, 10 Oct 2017 02:20:47 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 8: Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/1319/ -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 8 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Reviewer: Tim Armstrong Gerrit-Comment-Date: Mon, 09 Oct 2017 22:16:43 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 8: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 8 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Reviewer: Tim Armstrong Gerrit-Comment-Date: Mon, 09 Oct 2017 22:16:34 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 7: Verified-1 Build failed: https://jenkins.impala.io/job/gerrit-verify-dryrun/1316/ -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 7 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Mon, 09 Oct 2017 22:13:04 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 7: Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/1316/ -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 7 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Impala Public Jenkins Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Mon, 09 Oct 2017 18:22:06 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 6: Code-Review+2 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 6 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Sat, 07 Oct 2017 00:04:54 + Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); > I followed Michael's foot steps and looked at the ~17 callers of DoRpc. Far works for me. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Sat, 07 Oct 2017 00:03:15 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 6: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: > Maybe we should include the RPC name in the log message and that will disam I followed Michael's foot steps and looked at the ~17 callers of DoRpc. Far from all of them log. I'm now proposing we do this patch without the DoRpc() changes. From a performance standpoint, if you're timing out on RPCs, the backtrace is the least of your problems, and, yet, I think knowing which RPC is timing out is very helpful. I wasn't able to see a quick way to get the name of the RPC without discouraged C++ shenanigans. I checked that the Thrift Exception doesn't have that, nor do the Thrift structs seem to have self-identifying information. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 6 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Fri, 06 Oct 2017 23:28:37 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Hello Michael Ho, Sailesh Mukil, Alex Behm, Mostafa Mokhtar, Dan Hecht, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8100 to look at the new patch set (#6). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. IMPALA-5940: Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. The following messages will no longer log: "Failed to codegen MaterializeTuple() due to unsupported type: $0" "Not implemented for this format." "ScalarFnCall Codegen not supported for CHAR" "Could not codegen CodegenMaterializeExprs: " "Could not codegen TupleRowComparator::Compare(): $0" These codegen related messages were happening at every execution node, and were therefore very common. In addition, the following messages, which were very frequent in the logs, now will log, but without the back trace: "Query Id ... not found." To do this, I changed them from logging implicitly via Status(...) to logging explicitly. I have not fixed this message: "... Client ... timed-out during recv call." It's in DoRpc(), and not all callers of DoRpc() have independent logging. For now, we'll trade a little bit of log spam for clearer debugging. The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. * Manual testing for one of the new back-trace-suppressed paths: $ impala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:21000 GetRuntimeProfile 'beeswaxd.ttypes.QueryHandle()' Traceback (most recent call last): File "shell/gen-py/ImpalaService/ImpalaService-remote", line 106, in pp.pprint(client.GetRuntimeProfile(eval(args[0]),)) File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 161, in GetRuntimeProfile return self.recv_GetRuntimeProfile() File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 184, in recv_GetRuntimeProfile raise result.error beeswaxd.ttypes.BeeswaxException: BeeswaxException(handle=QueryHandle(log_context='', id=''), log_context='', SQLState='HY000', _message='GetRuntimeProfile error: Query id 0:0 not found.\n', errorCode=0) $ grep 'Query id' logs/cluster/impalad.INFO | tail -n 1 I0926 20:29:09.44 6787 impala-server.cc:642] Query id 0:0 not found. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 --- M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/tuple.cc M be/src/service/impala-server.cc M be/src/util/tuple-row-compare.cc 6 files changed, 16 insertions(+), 15 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/00/8100/6 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 6 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 5: Code-Review+1 (1 comment) Please get have Michael do the +2 once the RPC logging stuff is settled (I'm not sure if he wants something done or not). http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: VLOG(1) << err; > I agree that removing the backtrace here is the right direction as 90% of t Maybe we should include the RPC name in the log message and that will disambiguate? -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 5 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Wed, 04 Oct 2017 17:12:45 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Michael Ho has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (2 comments) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); > Yea, the backtrace is not all that useful here. Forgot to add that. I was a I agree that removing the backtrace here is the right direction as 90% of the cases logged are from DataStreamSender and they are considered "harmless" in this case. The caller of this function from DataStreamSender is from DataStreamSender::Channel::DoTransmitDataRpc() which will react to a timeout error by retrying the recv part of the RPC repeatedly until success or a non-timeout related error is found. So, in that sense, the RECV_TIMEOUT error shouldn't be logged in GetSendStatus() until it hits other errors. I did a quick audit of all callers of DoRpc() and it appears that some callers didn't really log the error. So, it may still be a bit inconvenient in those cases but this can be made up by adding more logging in those cases instead. (e.g. CatalogOpExecutor::Exec) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@281 PS3, Line 281: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); > same set of comment/question This one is definitely fine to not log the backtrace as we know this is coming from DataStreamSender for sure. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Michael Ho Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Tue, 03 Oct 2017 18:29:16 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Sailesh Mukil has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 5: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: VLOG(1) << err; > That re-log of the error doesn't include the backtrace though. So I don't t Yea, the backtrace is not all that useful here. Forgot to add that. I was alluding to the fact that from GetSendStatus() we would know that this was a RPC failure for the DataStreamSender specifically. Similarly, other clients of the RPC subsystem would log this error separately, and we would know what RPC failed. So we don't need the backtrace. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 5 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Tue, 03 Oct 2017 17:46:10 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); > I think it should be fine, since we re-log the error here anyway: That re-log of the error doesn't include the backtrace though. So I don't think it has bearing on whether eliminating the backtrace is okay. That said, it's probably still okay to avoid the BT here. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Tue, 03 Oct 2017 17:34:00 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Sailesh Mukil has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 5: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: VLOG(1) << err; > Michael/Sailesh - are you guys okay with eliminating this backtrace, or hav I think it should be fine, since we re-log the error here anyway: https://github.com/apache/incubator-impala/blob/e993b9712c81dfb66fdf65bb5269cdc38a8eef18/be/src/runtime/data-stream-sender.cc#L278 Same for RetryRpcRecv() as well. Michael can confirm if it's okay too. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 5 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Sailesh Mukil Gerrit-Comment-Date: Tue, 03 Oct 2017 17:23:03 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Hello Tim Armstrong, Alex Behm, Mostafa Mokhtar, Dan Hecht, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8100 to look at the new patch set (#4). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. IMPALA-5940: Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. The following messages will no longer log: "Failed to codegen MaterializeTuple() due to unsupported type: $0" "Not implemented for this format." "ScalarFnCall Codegen not supported for CHAR" "Could not codegen CodegenMaterializeExprs: " "Could not codegen TupleRowComparator::Compare(): $0" These codegen related messages were happening at every execution node, and were therefore very common. In addition, the following messages, which were very frequent in the logs, now will log, but without the back trace: "... Client ... timed-out during recv call." "Query Id ... not found." To do this, I changed them from logging implicitly via Status(...) to logging explicitly. The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. * Manual testing for one of the new back-trace-suppressed paths: $ impala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:21000 GetRuntimeProfile 'beeswaxd.ttypes.QueryHandle()' Traceback (most recent call last): File "shell/gen-py/ImpalaService/ImpalaService-remote", line 106, in pp.pprint(client.GetRuntimeProfile(eval(args[0]),)) File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 161, in GetRuntimeProfile return self.recv_GetRuntimeProfile() File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 184, in recv_GetRuntimeProfile raise result.error beeswaxd.ttypes.BeeswaxException: BeeswaxException(handle=QueryHandle(log_context='', id=''), log_context='', SQLState='HY000', _message='GetRuntimeProfile error: Query id 0:0 not found.\n', errorCode=0) $ grep 'Query id' logs/cluster/impalad.INFO | tail -n 1 I0926 20:29:09.44 6787 impala-server.cc:642] Query id 0:0 not found. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 --- M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/client-cache.h M be/src/runtime/tuple.cc M be/src/service/impala-server.cc M be/src/util/tuple-row-compare.cc 7 files changed, 26 insertions(+), 19 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/00/8100/4 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 4 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (4 comments) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc File be/src/exec/hdfs-avro-scanner.cc: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc@972 PS3, Line 972: return Status::Expected(Substitute( > Yes that's correct. I double-checked a variant here. It shows up there. (It's not from this Avro code path, but they're similar. I wasn't able to quickly find an avro test table with the right types...) [philip-dev.gce.cloudera.com:21000] > use functional_rc; Query: use functional_rc [philip-dev.gce.cloudera.com:21000] > create table t2 as select * from alltypes; Query: create table t2 as select * from alltypes ... HDFS_SCAN_NODE (id=0):(Total: 35.999ms, non-child: 35.999ms, % non-child: 100.00%) Hdfs split stats (:<# splits>/): -1:8/140.12 KB ExecOption: RC_FILE Codegen Disabled: Not implemented for this format. http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@243 PS3, Line 243: string err = strings::Substitute("Client $0 timed-out during recv call.", TNetworkAddressToString(address_)); > long line done. http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@281 PS3, Line 281: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); > same set of comment/question done. http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/tuple.cc File be/src/runtime/tuple.cc: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/tuple.cc@309 PS3, Line 309: stringstream ss; : ss << "Could not codegen CodegenMaterializeExprs: " << status.GetDetail(); > okay to ignore, but could clean that up with Substitute() Done -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Comment-Date: Fri, 29 Sep 2017 19:51:08 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Tim Armstrong has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc File be/src/exec/hdfs-avro-scanner.cc: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc@972 PS3, Line 972: return Status::Expected(Substitute( > Michael/Tim - these will show up in the runtime profile still, right? so ok Yes that's correct. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Reviewer: Tim Armstrong Gerrit-Comment-Date: Fri, 29 Sep 2017 00:15:09 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 3: (5 comments) http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc File be/src/exec/hdfs-avro-scanner.cc: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/exec/hdfs-avro-scanner.cc@972 PS3, Line 972: return Status::Expected(Substitute( Michael/Tim - these will show up in the runtime profile still, right? so okay to avoid logging them, right? http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@243 PS3, Line 243: string err = strings::Substitute("Client $0 timed-out during recv call.", TNetworkAddressToString(address_)); long line http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@246 PS3, Line 246: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); Michael/Sailesh - are you guys okay with eliminating this backtrace, or have we found it useful for debugging in the field? http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/client-cache.h@281 PS3, Line 281: return Status::Expected(ErrorMsg(TErrorCode::RPC_RECV_TIMEOUT, err)); same set of comment/question http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/tuple.cc File be/src/runtime/tuple.cc: http://gerrit.cloudera.org:8080/#/c/8100/3/be/src/runtime/tuple.cc@309 PS3, Line 309: stringstream ss; : ss << "Could not codegen CodegenMaterializeExprs: " << status.GetDetail(); okay to ignore, but could clean that up with Substitute() -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Dan Hecht Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Comment-Date: Fri, 29 Sep 2017 00:07:02 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Hello Alex Behm, Mostafa Mokhtar, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8100 to look at the new patch set (#3). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. IMPALA-5940: Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. The following messages will no longer log: "Failed to codegen MaterializeTuple() due to unsupported type: $0" "Not implemented for this format." "ScalarFnCall Codegen not supported for CHAR" "Could not codegen CodegenMaterializeExprs: " "Could not codegen TupleRowComparator::Compare(): $0" These codegen related messages were happening at every execution node, and were therefore very common. In addition, the following messages, which were very frequent in the logs, now will log, but without the back trace: "... Client ... timed-out during recv call." "Query Id ... not found." To do this, I changed them from logging implicitly via Status(...) to logging explicitly. The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. * Manual testing for one of the new back-trace-suppressed paths: $ impala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:21000 GetRuntimeProfile 'beeswaxd.ttypes.QueryHandle()' Traceback (most recent call last): File "shell/gen-py/ImpalaService/ImpalaService-remote", line 106, in pp.pprint(client.GetRuntimeProfile(eval(args[0]),)) File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 161, in GetRuntimeProfile return self.recv_GetRuntimeProfile() File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 184, in recv_GetRuntimeProfile raise result.error beeswaxd.ttypes.BeeswaxException: BeeswaxException(handle=QueryHandle(log_context='', id=''), log_context='', SQLState='HY000', _message='GetRuntimeProfile error: Query id 0:0 not found.\n', errorCode=0) $ grep 'Query id' logs/cluster/impalad.INFO | tail -n 1 I0926 20:29:09.44 6787 impala-server.cc:642] Query id 0:0 not found. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 --- M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/client-cache.h M be/src/runtime/tuple.cc M be/src/service/impala-server.cc M be/src/util/tuple-row-compare.cc 7 files changed, 23 insertions(+), 17 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/00/8100/3 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 3 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 2: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/2/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/2/be/src/runtime/client-cache.h@243 PS2, Line 243: return Status::NoTrace(TErrorCode::RPC_RECV_TIMEOUT, strings::Substitute( > Is it necessary to have Status write the message to the log? is it not suf Yep, you're right. Much lighter change. I'll update. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 2 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Comment-Date: Wed, 27 Sep 2017 03:20:01 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Mostafa Mokhtar has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. Patch Set 2: (1 comment) http://gerrit.cloudera.org:8080/#/c/8100/2/be/src/runtime/client-cache.h File be/src/runtime/client-cache.h: http://gerrit.cloudera.org:8080/#/c/8100/2/be/src/runtime/client-cache.h@243 PS2, Line 243: return Status::NoTrace(TErrorCode::RPC_RECV_TIMEOUT, strings::Substitute( Is it necessary to have Status write the message to the log? is it not sufficient to write an info message via LOG.info. -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 2 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Comment-Date: Tue, 26 Sep 2017 23:08:09 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Hello Alex Behm, Mostafa Mokhtar, I'd like you to reexamine a change. Please visit http://gerrit.cloudera.org:8080/8100 to look at the new patch set (#2). Change subject: IMPALA-5940: Avoid log spew by using Status::Expected. .. IMPALA-5940: Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. The following messages will no longer log: "Failed to codegen MaterializeTuple() due to unsupported type: $0" "Not implemented for this format." "ScalarFnCall Codegen not supported for CHAR" "Could not codegen CodegenMaterializeExprs: " "Could not codegen TupleRowComparator::Compare(): $0" These codegen related messages were happening at every execution node, and were therefore very common. In addition, the following messages, which were very frequent in the logs, now will log, but without the back trace: "... Client ... timed-out during recv call." "Query Id ... not found." To preserve the source of the messages, I used preprocessor macros __FILE__ and __LINE__ and stuffed them into the error string. As you can see in the worked example in the testing section below, __FILE__ includes the full source code path, which is uglier than the logging equivalent. (glog has a helper called "const_basename" which handles this at https://github.com/google/glog/blob/2a6df66252d266080489c310b8146e63b66b2add/src/utilities.cc#L279) The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. * Manual testing for one NoTrace code path: $ impala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:21000 GetRuntimeProfile 'beeswaxd.ttypes.QueryHandle()' Traceback (most recent call last): File "shell/gen-py/ImpalaService/ImpalaService-remote", line 106, in pp.pprint(client.GetRuntimeProfile(eval(args[0]),)) File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 161, in GetRuntimeProfile return self.recv_GetRuntimeProfile() File "/home/philip/src/impala/shell/gen-py/ImpalaService/ImpalaService.py", line 184, in recv_GetRuntimeProfile raise result.error beeswaxd.ttypes.BeeswaxException: BeeswaxException(handle=QueryHandle(log_context='', id=''), log_context='', SQLState='HY000', _message='GetRuntimeProfile error: /home/philip/src/impala/be/src/service/impala-server.cc:641: Query id 0:0 not found.\n', errorCode=0) $ tail -n 1 logs/cluster/impalad.INFO I0926 14:51:19.867837 30582 status.cc:147] /home/philip/src/impala/be/src/service/impala-server.cc:641: Query id 0:0 not found. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 --- M be/src/common/status.cc M be/src/common/status.h M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/client-cache.h M be/src/runtime/tuple.cc M be/src/service/impala-server.cc M be/src/util/tuple-row-compare.cc 9 files changed, 70 insertions(+), 27 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/00/8100/2 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: newpatchset Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 2 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger
[Impala-ASF-CR] IMPALA-5940. Avoid log spew by using Status::Expected.
Philip Zeyliger has posted comments on this change. ( http://gerrit.cloudera.org:8080/8100 ) Change subject: IMPALA-5940. Avoid log spew by using Status::Expected. .. Patch Set 1: (1 comment) Thanks for the review! I added in the two messages that Mostafa mentioned on the JIRA. Doing so introduced two complexities: * Whereas I believe we could never log the messages in the first draft, the new messages being silenced here (especially RPC timeout) should be logged. * Now that there's no stack trace, the fact that the messages come as being from "status.cc" is not useful. I see the following ways forward: * Use draft 1 to silence the easy messages; ignore this new draft 2. * Use draft 2. Notably, it uses the __FILE__ preprocessor macro. __func__ is also a possibility. * Change the usage pattern. For example STATUS_AND_LOG(...) could be a macro that does VLOG and the Status generation. I was very hesitant to add macros for this so didn't go that route. * Something else? I want to highlight a few more things about patch 2: * I started off with a signature like Status(..., bool silent, bool omit_backtrace), but there were only 3 possible good states. I had bugs in my implementation, so decided on an enum instead. It's all private, so there's little API risk here. * There's a copy of ErrorMsg going on when Status::NoTrace() takes an error code and a string. We do several of them in various Status signatures. Given that we used to also compute an entire back trace, I think this is ok. * I didn't add a new test. I didn't find any tests that look like they're testing our logging behavior. Happy for suggestions, though I think it's overkill. * I don't know how to reproduce RPC timeouts. I "kill -STOP"ed an impalad, but that wasn't enough. Curious for pointers. http://gerrit.cloudera.org:8080/#/c/8100/1//COMMIT_MSG Commit Message: http://gerrit.cloudera.org:8080/#/c/8100/1//COMMIT_MSG@7 PS1, Line 7: IMPALA-5940. Avoid log spew by using Status::Expected. > IMPALA-5940: (colon not dot) Done -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-Change-Number: 8100 Gerrit-PatchSet: 1 Gerrit-Owner: Philip ZeyligerGerrit-Reviewer: Alex Behm Gerrit-Reviewer: Mostafa Mokhtar Gerrit-Reviewer: Philip Zeyliger Gerrit-Comment-Date: Tue, 26 Sep 2017 23:03:30 + Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5940. Avoid log spew by using Status::Expected.
Philip Zeyliger has uploaded a new change for review. http://gerrit.cloudera.org:8080/8100 Change subject: IMPALA-5940. Avoid log spew by using Status::Expected. .. IMPALA-5940. Avoid log spew by using Status::Expected. In IMPALA-5926, we fixed a case where closing the session triggered a stack trace in the logs which impacted performance for short-running queries. Looking at log files from several active clusters, I identified a few other cases where we could clean up log spew with the same (trivial) approach. In practice, the expected messages here are saying that we don't support codegen for the given file formats or data types. Because codegen happens at every execution node, these messages are very common in the log files. The snippet I used to identify these was: find . -type f -name '*IMPALAD*.gz' | xargs gzcat | awk '/^I/ { if(x) { print x; } x = "" } /status.cc/ { x=" "; } { if(x) { x=x $0 } }' | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUERYID/g' | tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c | sort -n | tee output.txt I also analyzed some logs using SQL, against a pre-processed logs table: with v as ( select regexp_replace( regexp_replace( translate(substr(message, 42), "\n\t", " "), "[a-zA-Z0-9.-]*[.][a-zA-Z0-9-]*:[0-9]*", ""), "@.*$", "@@@...") as m from logs_table where `class`="status.cc") select m, count(*) from v group by 1 order by 2 desc limit 100 Testing: * Automated tests. Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 --- M be/src/exec/hdfs-avro-scanner.cc M be/src/exec/hdfs-scan-node-base.cc M be/src/exprs/scalar-fn-call.cc M be/src/runtime/tuple.cc M be/src/util/tuple-row-compare.cc 5 files changed, 7 insertions(+), 7 deletions(-) git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/00/8100/1 -- To view, visit http://gerrit.cloudera.org:8080/8100 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-MessageType: newchange Gerrit-Change-Id: I38088482377a1c3e794a9c8178ef83f29957a330 Gerrit-PatchSet: 1 Gerrit-Project: Impala-ASF Gerrit-Branch: master Gerrit-Owner: Philip Zeyliger