Uploaded image for project: 'HBase'
  1. HBase
  2. HBASE-24543

ScheduledChore logging is too chatty, replace with metrics



    • Improvement
    • Status: Open
    • Minor
    • Resolution: Unresolved
    • None
    • None
    • metrics, Operability
    • None


      ScheduledChore logs at DEBUG level the execution time of each chore.

      We used to log an average execution time across all chores every five minutes, which by consensus was judged to not be useful. Derived metrics like averages or histograms should be calculated per chore. So we modified the logging to dump the chore execution time each time it runs, to facilitate such calculations with the log aggregation and searching tool of choice. Per chore execution logging is more useful, in that sense, but may be too chatty. This is not unexpected but let me provide my observations so we can revisit this.

      On the master, for example, this is logged every second:

      2020-06-11 16:35:28,263 DEBUG [master/apurtell-ltm:8100.splitLogManager..Chore.1] hbase.ScheduledChore: SplitLogManager Timeout Monitor execution time: 0 ms.

      Does the value of these lines outweigh the cost of 86,400 log lines per day per master instance? (At least.)

      On the regionserver it is somewhat better, these are logged every 10 seconds:

      2020-06-11 16:37:57,203 DEBUG [regionserver/apurtell-ltm:8120.Chore.1] hbase.ScheduledChore: CompactionChecker execution time: 0 ms.
      2020-06-11 16:37:57,203 DEBUG [regionserver/apurtell-ltm:8120.Chore.1] hbase.ScheduledChore: MemstoreFlusherChore execution time: 0 ms.

      So that will be 17,280 log lines per day per regionserver. (At least.)

      These could be moved to TRACE level, perhaps.

      I propose we replace this logging with histogram metrics. There should be a separate metric for each distinct chore classname, allocated as needed.




            sandeep.pal Sandeep Pal
            apurtell Andrew Kyle Purtell
            0 Vote for this issue
            3 Start watching this issue