[KUDU-1799] AsyncKuduClient.discoverTablets has very expensive logging

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Fix Version/s: 1.2.0
• Labels: impala
• Assignee: Dan Burkert
• Reporter: Matthew Jacobs
• Created: 09/Dec/16 20:19
• Updated: 12/Dec/16 03:13
• Resolved: 12/Dec/16 03:13

Description

Impala finds that the following logging is causing extreme contention in concurrent planning of queries containing tables w/ a large number of partitions.

      LOG.info("Learned about tablet {} for table '{}' with partition {}",
               rt.getTabletId(), tableName, rt.getPartition());

This stack dominates the cost of planning:

org.apache.log4j.Category.callAppenders(LoggingEvent)	165,411	6,692,346,585,303
   org.apache.log4j.Category.forcedLog(String, Priority, Object, Throwable)	165,411	6,692,346,585,303
      org.apache.log4j.Category.log(String, Priority, Object, Throwable)	165,411	6,692,346,585,303
         org.slf4j.impl.Log4jLoggerAdapter.info(String, Object[])	165,411	6,692,346,585,303
            org.apache.kudu.client.AsyncKuduClient.discoverTablets(KuduTable, byte[], List, long)	165,411	6,692,346,585,303
               org.apache.kudu.client.AsyncKuduClient$MasterLookupCB.call(Master$GetTableLocationsResponsePB)	165,411	6,692,346,585,303
                  org.apache.kudu.client.AsyncKuduClient$MasterLookupCB.call(Object)	165,411	6,692,346,585,303
                     com.stumbleupon.async.Deferred.doCall(Callback)	165,411	6,692,346,585,303