HBase
  1. HBase
  2. HBASE-4193

Enhance RPC debug logging to provide more details on call contents

    Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.92.0
    • Component/s: IPC/RPC
    • Labels:
      None

      Description

      The current HBaseServer debug logging, while verbose, doesn't provide much information on the actual contents of RPC calls being handled. This makes it difficult to diagnose why some calls make take much longer to process that others. Have more information on the size of client calls, and the contents of those calls (especially in the case of batch or multi operations) would provide a lot more context for tracking down issues.

      1. HBASE-4193.patch
        9 kB
        Gary Helmling
      2. HBASE-4193_final.patch
        11 kB
        Gary Helmling

        Activity

        Hide
        Gary Helmling added a comment -

        This patch enhances the debug logging output of HBaseServer to include the raw size of the client request and some introspected details of the contents.

        The enhanced logging will produce lines like:

        2011-08-11 12:29:49,836 DEBUG [IPC Server handler 2 on 36501] ipc.WritableRpcEngine$Server(318): Call #540; Served: HRegionInterface#multi queueTime=0 processingTime=461 contents=139 values [ min=5 max=5 avg=5 ], 139 Puts, 139 KeyValues
        2011-08-11 12:29:49,894 DEBUG [IPC Server handler 3 on 54615] ipc.WritableRpcEngine$Server(318): Call #537; Served: HRegionInterface#multi queueTime=0 processingTime=546 contents=219 values [ min=5 max=5 avg=5 ], 219 Puts, 219 KeyValues
        

        There are 2 key changes from the current logging:

        1. include the call ID (for easier cross referencing with other log messages
        2. add the contents=... output with counts of objects in the request and simple stats on value sizes from KVs

        In addition, the lines shown above have been moved to a separate logger (org.apache.hadoop.ipc.HBaseServer.trace), so that they can be enabled separately from other IPC debugging output. Unless explicitly enabled, they don't incur any additional overhead.

        Show
        Gary Helmling added a comment - This patch enhances the debug logging output of HBaseServer to include the raw size of the client request and some introspected details of the contents. The enhanced logging will produce lines like: 2011-08-11 12:29:49,836 DEBUG [IPC Server handler 2 on 36501] ipc.WritableRpcEngine$Server(318): Call #540; Served: HRegionInterface#multi queueTime=0 processingTime=461 contents=139 values [ min=5 max=5 avg=5 ], 139 Puts, 139 KeyValues 2011-08-11 12:29:49,894 DEBUG [IPC Server handler 3 on 54615] ipc.WritableRpcEngine$Server(318): Call #537; Served: HRegionInterface#multi queueTime=0 processingTime=546 contents=219 values [ min=5 max=5 avg=5 ], 219 Puts, 219 KeyValues There are 2 key changes from the current logging: include the call ID (for easier cross referencing with other log messages add the contents=... output with counts of objects in the request and simple stats on value sizes from KVs In addition, the lines shown above have been moved to a separate logger (org.apache.hadoop.ipc.HBaseServer.trace), so that they can be enabled separately from other IPC debugging output. Unless explicitly enabled, they don't incur any additional overhead.
        Hide
        Andrew Purtell added a comment -

        +1

        Show
        Andrew Purtell added a comment - +1
        Hide
        stack added a comment -

        +1 Excellent!

        Would imagine once enabled that it will be super expensive logging but then I like have you labelled TRACELOG so that sets up right expectation.

        Add license on commit to Objects.java.

        Show
        stack added a comment - +1 Excellent! Would imagine once enabled that it will be super expensive logging but then I like have you labelled TRACELOG so that sets up right expectation. Add license on commit to Objects.java.
        Hide
        Gary Helmling added a comment -

        Final patch committed to trunk.

        Show
        Gary Helmling added a comment - Final patch committed to trunk.
        Hide
        Gary Helmling added a comment -

        Committed to trunk. Thanks for the reviews!

        Show
        Gary Helmling added a comment - Committed to trunk. Thanks for the reviews!
        Hide
        Hudson added a comment -

        Integrated in HBase-TRUNK #2111 (See https://builds.apache.org/job/HBase-TRUNK/2111/)
        HBASE-4193 Enhance RPC debug logging with details on call contents

        garyh :
        Files :

        • /hbase/trunk/conf/log4j.properties
        • /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
        • /hbase/trunk/CHANGES.txt
        • /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
        • /hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java
        Show
        Hudson added a comment - Integrated in HBase-TRUNK #2111 (See https://builds.apache.org/job/HBase-TRUNK/2111/ ) HBASE-4193 Enhance RPC debug logging with details on call contents garyh : Files : /hbase/trunk/conf/log4j.properties /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java /hbase/trunk/CHANGES.txt /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java /hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java

          People

          • Assignee:
            Gary Helmling
            Reporter:
            Gary Helmling
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development