Page MenuHomePhabricator

Reducing logging levels when running a Hive query
Closed, ResolvedPublic

Description

(Note: This is not an urgent/important request but I was talking to @elukey on IRC and so decided to document this here.)

Hi. I usually run a Hive query from Spark and then while it executes, I move on to something else and come back to check the result after a while. This is especially true for queries that take some time to finish executing.

But after the query has finished and the result is displayed, I see some logging messages, such as the one below that make it difficult to find the output result:

21/02/16 17:19:22 INFO DAGScheduler: Executor lost: 92 (epoch 2)
21/02/16 17:19:22 INFO BlockManagerMasterEndpoint: Trying to remove executor 92 from BlockManagerMaster.
21/02/16 17:19:22 INFO BlockManagerMasterEndpoint: Removing block manager BlockManagerId(92, analytics1070.eqiad.wmnet, 38763, None)
21/02/16 17:19:22 INFO BlockManagerMaster: Removed 92 successfully in removeExecutor
21/02/16 17:19:22 INFO YarnScheduler: Executor 92 on analytics1070.eqiad.wmnet killed by driver.
21/02/16 17:19:22 INFO ExecutorAllocationManager: Existing executor 92 has been removed (new total is 0)

As well as cleanup messages,

21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 76
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 142
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 200
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 192
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 81
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 164
21/02/16 17:25:19 INFO ContextCleaner: Cleaned accumulator 155

These are repeated for many lines and I have noticed they don't happen immediately after the query finishes but after some idling.

Is there a way to suppress/filter these messages so that I can just observe the result and not worry about losing it in the backlog? Thanks!

Event Timeline

I edited the task but I wanted to add here as well that this happens when I run the Hive query from Spark.

razzi moved this task from Incoming to Operational Excellence on the Analytics board.
BTullis added a project: Analytics-Kanban.
BTullis added a subscriber: Ottomata.

@Ottomata drew my attention to this task and think I may have an idea why it's happening, so I'm going to try to fix it at the same time as T279304.
Ultimately, I believe that the cause is the same as for T279304: Incorrect log4j configuration on hive servers causing excessive logging, which is that the log4j settings on the hive cluster are slightly misconfigured.

@ssingh - Can you confirm if you're still observing this behaviour? If so, hopefully I'll have something for you to test before long, to see if it's resolved.

Hi @BTullis: It's been a while since I ran a query on Hive but I am happy to help test this, so please let me know. Thanks!

Hi @ssingh - I've deployed the change that I believe will make hive less noisy in production.
Specifically, it should reduce the log level from INFO to WARN for both client queries and for the server-side components.

Whilst the hive server and metadata store have yet to be restarted, I think that this change will immediately make your client queries quieter by removing those INFO messages that you mentioned.

If there's a convenient way that you can run a query to verify whether or not this works, I'd be grateful.

I'm going to mark this ticket as resolved, since I believe that the logging level for hive client queries has been lowered from INFO to WARN.
However, I'll behappy to reopen it if @ssingh or anyone else reports that it has not worked as hoped.

Hi @BTullis: I just ran a query and it is indeed quieter as compared to the last time I ran it, when I couldn't even see the output. Thanks very much for working on this change!

Great! Thanks for confirming.