impala-reviews mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Philip Zeyliger (Code Review)" <ger...@cloudera.org>
Subject [Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected.
Date Fri, 06 Oct 2017 23:28:17 GMT
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]*",
          "<host>"),
        "@.*$", "@@@...") 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 <module>
      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.999944  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 Zeyliger <philip@cloudera.com>
Gerrit-Reviewer: Alex Behm <alex.behm@cloudera.com>
Gerrit-Reviewer: Dan Hecht <dhecht@cloudera.com>
Gerrit-Reviewer: Michael Ho <kwho@cloudera.com>
Gerrit-Reviewer: Mostafa Mokhtar <mmokhtar@cloudera.com>
Gerrit-Reviewer: Philip Zeyliger <philip@cloudera.com>
Gerrit-Reviewer: Sailesh Mukil <sailesh@cloudera.com>

Mime
  • Unnamed multipart/alternative (inline, 8-Bit, 0 bytes)
View raw message