[GOBBLIN-1842] Add timers to GobblinMCEWriter

[jack-moseley]

Dear Gobblin maintainers,

Please accept this PR. I understand that it will not be reviewed until I have checked off all the steps below!

JIRA

• My PR addresses the following Gobblin JIRA issues and references them in the PR title. For example, "[GOBBLIN-XXX] My Gobblin PR"
  • https://issues.apache.org/jira/browse/GOBBLIN-1842

Description

• Here are some details about my PR, including screenshots (if applicable):
  Add timers for:
• hivespec computation
• write for each metadata writer
• flush for each metadata writer

These timers are set up with a 1 hour sliding window, so the statistics will be for the last hour of execution. The timers are registered with metric context so they will send metrics through gobblin's metric framework. Also, added logging during every flush interval (every 1 min) which logs the current mean/99th percentile of every timer, so it is easier to see where time is being spent.

Tests

• My PR adds the following unit tests OR does not need testing for this extremely good reason:
  Ran test pipeline. Example timer logs:

2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - begin flushing 0 records
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.iceberg.writer.IcebergMetadataWriter.write 1 hour mean duration: 10 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.iceberg.writer.IcebergMetadataWriter.write 1 hour 99th percentile duration: 104 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.hive.writer.HiveMetadataWriter.write 1 hour mean duration: 14 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.hive.writer.HiveMetadataWriter.write 1 hour 99th percentile duration: 213 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.iceberg.writer.IcebergMetadataWriter.flush 1 hour mean duration: 3756 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.iceberg.writer.IcebergMetadataWriter.flush 1 hour 99th percentile duration: 69138 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.hive.writer.HiveMetadataWriter.flush 1 hour mean duration: 0 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer org.apache.gobblin.hive.writer.HiveMetadataWriter.flush 1 hour 99th percentile duration: 1 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer hiveSpec.computation 1 hour mean duration: 10 ms
2023-06-13 11:16:58 PDT INFO  [StreamModelTaskRunner] org.apache.gobblin.iceberg.writer.GobblinMCEWriter  - Timer hiveSpec.computation 1 hour 99th percentile duration: 19 ms

Commits

• My commits all reference JIRA issues in their subject lines, and I have squashed multiple commits if they address the same issue. In addition, my commits follow the guidelines from "How to write a good git commit message":
  1. Subject is separated from body by a blank line
  2. Subject is limited to 50 characters
  3. Subject does not end with a period
  4. Subject uses the imperative mood ("add", not "adding")
  5. Body wraps at 72 characters
  6. Body explains "what" and "why", not "how"

[ZihanLi58]

As I see more time spending in flush, can we consider add more detail breaking down there, like how much time we spend to commit a transaction etc...

[codecov-commenter]

Codecov Report

Merging #3703 (9032fe2) into master (a00b57c) will decrease coverage by 0.04%.
The diff coverage is 87.09%.

@@             Coverage Diff              @@
##             master    #3703      +/-   ##
============================================
- Coverage     46.89%   46.86%   -0.04%     
- Complexity    10772    10807      +35     
============================================
  Files          2138     2141       +3     
  Lines         84139    84465     +326     
  Branches       9357     9385      +28     
============================================
+ Hits          39456    39583     +127     
- Misses        41078    41279     +201     
+ Partials       3605     3603       -2     

Impacted Files	Coverage Δ
...apache/gobblin/hive/writer/HiveMetadataWriter.java	0.00% <0.00%> (ø)
...pache/gobblin/iceberg/writer/GobblinMCEWriter.java	77.69% <93.18%> (+2.26%)	⬆️
.../gobblin/iceberg/writer/IcebergMetadataWriter.java	70.94% <100.00%> (-1.43%)	⬇️

... and 39 files with indirect coverage changes

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[jack-moseley]

As I see more time spending in flush, can we consider add more detail breaking down there, like how much time we spend to commit a transaction etc...

Hmm, so you mean more timers within the indvidual writers? Yeah I guess I'll add some there, although I would think during flush the time is spent pretty much all in the commit. I guess it would be good to confirm that sending audit/commit events etc. is not taking much time.

[ZihanLi58]

+1