[HIVE-7574] CommonJoinOperator.checkAndGenObject calls LOG.Trace per row from probe side in a HashMap join consuming 4% of the CPU

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.13.1
• Fix Version/s: 0.14.0
• Component/s: Query Processor
• Labels: perfomance
• Assignee: Mostafa Mokhtar
• Reporter: Mostafa Mokhtar
• Created: 31/Jul/14 19:40
• Updated: 13/Nov/14 19:42
• Resolved: 06/Aug/14 21:34

Description

In Map join Log4JLogger.trace takes 4% of the CPU time as it gets called per row from the probe side by CommonJoinOperator.genAllOneUniqueJoinObject.

Fix is to remove the logging code code below from CommonJoinOperator.genAllOneUniqueJoinObject:

if (allOne) {
        LOG.info("calling genAllOneUniqueJoinObject");
        genAllOneUniqueJoinObject();
        LOG.info("called genAllOneUniqueJoinObject");
      } else {
        LOG.trace("calling genUniqueJoinObject");
        genUniqueJoinObject(0, 0);
        LOG.trace("called genUniqueJoinObject");
      }

And

    if (!hasEmpty && !mayHasMoreThanOne) {
        LOG.trace("calling genAllOneUniqueJoinObject");
        genAllOneUniqueJoinObject();
        LOG.trace("called genAllOneUniqueJoinObject");
      } else if (!hasEmpty && !hasLeftSemiJoin) {
        LOG.trace("calling genUniqueJoinObject");
        genUniqueJoinObject(0, 0);
        LOG.trace("called genUniqueJoinObject");
      } else {
        LOG.trace("calling genObject");
        genJoinObject();
        LOG.trace("called genObject");
      }

This is the call stack

Stack Trace	Sample Count	Percentage(%)
hadoop.hive.ql.exec.MapJoinOperator.processOp(Object, int)	388	75.486
   hadoop.hive.ql.exec.CommonJoinOperator.checkAndGenObject()	121	23.541
      hadoop.hive.ql.exec.CommonJoinOperator.genAllOneUniqueJoinObject()	92	17.899
      commons.logging.impl.Log4JLogger.trace(Object)	20	3.891
         log4j.Category.log(String, Priority, Object, Throwable)	20	3.891
            log4j.Category.getEffectiveLevel()	10	1.946