Mailing-List: contact reviews-help@impala.incubator.apache.org; run by ezmlm
Precedence: bulk
Message-Id: <201709262303.v8QN3tVX013045@ip-10-146-233-104.ec2.internal>
Date: Tue, 26 Sep 2017 23:03:55 +0000
From: "Philip Zeyliger (Code Review)" <gerrit@cloudera.org>
To: Alex Behm <alex.behm@cloudera.com>,
        Mostafa Mokhtar <mmokhtar@cloudera.com>, impala-cr@cloudera.com,
        reviews@impala.incubator.apache.org
Subject: =?UTF-8?Q?=5BImpala-ASF-CR=5D_IMPALA-5940=3A_Avoid_log_spew_by_using_Status=3A=3AExpected=2E=0A?=
In-Reply-To: <gerrit.1505845010000.I38088482377a1c3e794a9c8178ef83f29957a330@gerrit.cloudera.org>
References: <gerrit.1505845010000.I38088482377a1c3e794a9c8178ef83f29957a330@gerrit.cloudera.org>
Reply-To: philip@cloudera.com, impala-cr@cloudera.com, marcelk@gmail.com,
        mmokhtar@cloudera.com, alex.behm@cloudera.com,
        reviews@impala.incubator.apache.org
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
Content-Disposition: inline
User-Agent: Gerrit/2.14.2
Content-Type: multipart/alternative; boundary="mTwxsUF60fM="; charset=UTF-8
archived-at: Tue, 26 Sep 2017 23:04:04 -0000

--mTwxsUF60fM=
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable

Hello Alex Behm, Mostafa Mokhtar, 

I'd like you to reexamine a change=2E P=
lease visit

    http://gerrit=2Ecloudera=2Eorg:8080/8100

to look at the n=
ew patch set (#2)=2E

Change subject: IMPALA-5940: Avoid log spew by using =
Status::Expected=2E
=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=
=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=
=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=2E=
=2E=2E

IMPALA-5940: Avoid log spew by using Status::Expected=2E

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=2E Looking a=
t log files from several active clusters, I identified a few
other cases wh=
ere we could clean up log spew with the same (trivial)
approach=2E

The fol=
lowing messages will no longer log:

  "Failed to codegen MaterializeTuple(=
) due to unsupported type: $0"
  "Not implemented for this format=2E"
  "Sc=
alarFnCall Codegen not supported for CHAR"
  "Could not codegen CodegenMate=
rializeExprs: "
  "Could not codegen TupleRowComparator::Compare(): $0"

Th=
ese codegen related messages were happening at every execution node, and we=
re
therefore very common=2E

In addition, the following messages, which wer=
e very frequent in the logs, now
will log, but without the back trace:

  "=
=2E=2E=2E Client =2E=2E=2E timed-out during recv call=2E"
  "Query Id =2E=
=2E=2E not found=2E"

To preserve the source of the messages, I used prepro=
cessor macros __FILE__ and
__LINE__ and stuffed them into the error string=
=2E As you can see in the worked
example in the testing section below, __FI=
LE__ includes the full source code
path, which is uglier than the logging e=
quivalent=2E (glog has a helper
called "const_basename" which handles this =
at
https://github=2Ecom/google/glog/blob/2a6df66252d266080489c310b8146e63b6=
6b2add/src/utilities=2Ecc#L279)

The snippet I used to identify these was:
=

  find =2E -type f -name '*IMPALAD*=2Egz' | xargs gzcat  | awk '/^I/ { if(=
x) { print x; } x =3D "" } /status=2Ecc/ { x=3D" "; } { if(x) { x=3Dx  $0 }=
 }'  | sed -e 's/0x[0-9a-fx]* //g' | sed -e 's/[0-9a-f]\{16\}:[0-9a-f]*/QUE=
RYID/g' |  tr -s '\t' ' ' | tr '[0-9]' 'N' | sort | uniq -c  | sort -n | te=
e output=2Etxt

I also analyzed some logs using SQL, against a pre-processe=
d logs table:

  with v as (
    select regexp_replace(
        regexp_repl=
ace(
          translate(substr(message, 42), "\n\t", "  "),
          "[a-=
zA-Z0-9=2E-]*[=2E][a-zA-Z0-9-]*:[0-9]*",
          "<host>"),
        "@=2E=
*$", "@@@=2E=2E=2E") as m
    from logs_table where `class`=3D"status=2Ecc"=
)
  select m, count(*) from v group by 1 order by 2 desc limit 100

Testing=
:
* Automated tests=2E
* Manual testing for one NoTrace code path:

  $ imp=
ala-python shell/gen-py/ImpalaService/ImpalaService-remote -h localhost:210=
00 GetRuntimeProfile 'beeswaxd=2Ettypes=2EQueryHandle()'
  Traceback (most =
recent call last):
    File "shell/gen-py/ImpalaService/ImpalaService-remot=
e", line 106, in <module>
      pp=2Epprint(client=2EGetRuntimeProfile(eval=
(args[0]),))
    File "/home/philip/src/impala/shell/gen-py/ImpalaService/I=
mpalaService=2Epy", line 161, in GetRuntimeProfile
      return self=2Erecv=
_GetRuntimeProfile()
    File "/home/philip/src/impala/shell/gen-py/ImpalaS=
ervice/ImpalaService=2Epy", line 184, in recv_GetRuntimeProfile
      raise=
 result=2Eerror
  beeswaxd=2Ettypes=2EBeeswaxException: BeeswaxException(ha=
ndle=3DQueryHandle(log_context=3D'', id=3D''), log_context=3D'', SQLState=
=3D'HY000', _message=3D'GetRuntimeProfile error: /home/philip/src/impala/be=
/src/service/impala-server=2Ecc:641: Query id 0:0 not found=2E\n', errorCod=
e=3D0)

  $ tail -n 1 logs/cluster/impalad=2EINFO
  I0926 14:51:19=2E867837=
 30582 status=2Ecc:147] /home/philip/src/impala/be/src/service/impala-serve=
r=2Ecc:641: Query id 0:0 not found=2E

Change-Id: I38088482377a1c3e794a9c81=
78ef83f29957a330
---
M be/src/common/status=2Ecc
M be/src/common/status=2Eh=

M be/src/exec/hdfs-avro-scanner=2Ecc
M be/src/exec/hdfs-scan-node-base=2Ec=
c
M be/src/exprs/scalar-fn-call=2Ecc
M be/src/runtime/client-cache=2Eh
M be=
/src/runtime/tuple=2Ecc
M be/src/service/impala-server=2Ecc
M be/src/util/t=
uple-row-compare=2Ecc
9 files changed, 70 insertions(+), 27 deletions(-)


=
  git pull ssh://gerrit=2Ecloudera=2Eorg:29418/Impala-ASF refs/changes/00/8=
100/2
-- 
To view, visit http://gerrit=2Ecloudera=2Eorg:8080/8100
To unsubs=
cribe, visit http://gerrit=2Ecloudera=2Eorg:8080/settings

Gerrit-Project: =
Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Cha=
nge-Id: I38088482377a1c3e794a9c8178ef83f29957a330
Gerrit-Change-Number: 810=
0
Gerrit-PatchSet: 2
Gerrit-Owner: Philip Zeyliger <philip@cloudera=2Ecom>
=
Gerrit-Reviewer: Alex Behm <alex=2Ebehm@cloudera=2Ecom>
Gerrit-Reviewer: Mo=
stafa Mokhtar <mmokhtar@cloudera=2Ecom>
Gerrit-Reviewer: Philip Zeyliger <p=
hilip@cloudera=2Ecom>

--mTwxsUF60fM=--