[Impala-ASF-CR] IMPALA-5940: Avoid log spew by using Status::Expected()

[Impala Public Jenkins (Code Review)]

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 Ho 
Tested-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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()

[Michael Ho (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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()

[Michael Ho (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 Ho 
Gerrit-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 (Code Review)]

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 (Code Review)]

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 Armstrong 
Tested-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 (Code Review)]

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 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 
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 (Code Review)]

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 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 
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 (Code Review)]

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 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 
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 (Code Review)]

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 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-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 (Code Review)]

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 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-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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.

[Philip Zeyliger (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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.

[Philip Zeyliger (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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.

[Philip Zeyliger (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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.

[Philip Zeyliger (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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 Zeyliger 
Gerrit-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 (Code Review)]

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