[HUDI-1707] Reduces log level for too verbose messages from info to debug level. #2714

vburenin · 2021-03-24T14:50:10Z

What is the purpose of the pull request

Some log messages are too verbose and some are not really readable, this PR is aimed at moving most verbose messages from info to debug level as well as improving print out of the configuration info in delta streamer.

Verify this pull request

This pull request is a trivial rework / code cleanup without any test coverage.

Has a corresponding JIRA in PR title & commit
Commit message is descriptive of the change
CI is green

yanghua · 2021-03-30T07:15:37Z

@liujinhui1994 Can you help to review this PR?

pratyakshsharma · 2021-04-04T12:39:13Z

hudi-sync/hudi-hive-sync/src/main/java/org/apache/hudi/hive/util/HiveSchemaUtil.java

@@ -109,7 +109,7 @@ public static SchemaDifference getSchemaDifference(MessageType storageSchema, Ma
        schemaDiffBuilder.addTableColumn(entry.getKey(), entry.getValue());
      }
    }
-    LOG.info("Difference between schemas: " + schemaDiffBuilder.build().toString());
+    LOG.debug("Difference between schemas: " + schemaDiffBuilder.build().toString());


guess we should not move this log message to debug?

It can be very large some times, that's why I moved it to debug. Schemas on our side are hundreds of pages long. However, if you find it very useful for yourself, I can move it back to info. Just let me know.

pratyakshsharma · 2021-04-04T12:47:39Z

@vburenin Can you please fix the build? There are test failures.

Just one minor comment from my side and rest looks good. :)

vburenin · 2021-04-04T19:40:33Z

I wonder what could cause those failures as the only change I made is log level and some extra config print out... unless tests are looking into the logs... which is not good.

codecov-io · 2021-04-04T19:44:23Z

Codecov Report

Merging #2714 (334ac44) into master (8d4a7fe) will decrease coverage by 5.21%.
The diff coverage is 32.00%.

@@             Coverage Diff              @@
##             master    #2714      +/-   ##
============================================
- Coverage     52.55%   47.34%   -5.22%     
+ Complexity     3707     3383     -324     
============================================
  Files           485      485              
  Lines         23172    23185      +13     
  Branches       2459     2463       +4     
============================================
- Hits          12179    10976    -1203     
- Misses         9922    11254    +1332     
+ Partials       1071      955     -116

Flag	Coverage Δ	Complexity Δ
hudicli	`40.29% <ø> (ø)`	`0.00 <ø> (ø)`
hudiclient	`∅ <ø> (∅)`	`0.00 <ø> (ø)`
hudicommon	`50.70% <83.33%> (+<0.01%)`	`0.00 <1.00> (ø)`
hudiflink	`56.57% <ø> (ø)`	`0.00 <ø> (ø)`
hudihadoopmr	`33.44% <ø> (ø)`	`0.00 <ø> (ø)`
hudisparkdatasource	`71.33% <ø> (ø)`	`0.00 <ø> (ø)`
hudisync	`45.70% <100.00%> (ø)`	`0.00 <0.00> (ø)`
huditimelineservice	`64.36% <50.00%> (ø)`	`0.00 <0.00> (ø)`
hudiutilities	`9.31% <0.00%> (-60.41%)`	`0.00 <0.00> (ø)`

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ	Complexity Δ
...apache/hudi/utilities/deltastreamer/DeltaSync.java	`0.00% <0.00%> (-71.09%)`	`0.00 <0.00> (-55.00)`
...i/utilities/deltastreamer/HoodieDeltaStreamer.java	`0.00% <0.00%> (-71.20%)`	`0.00 <0.00> (-18.00)`
.../utilities/transform/SqlQueryBasedTransformer.java	`0.00% <0.00%> (-75.00%)`	`0.00 <0.00> (-3.00)`
...di/common/table/timeline/HoodieActiveTimeline.java	`66.52% <50.00%> (-0.29%)`	`43.00 <0.00> (ø)`
...g/apache/hudi/timeline/service/RequestHandler.java	`73.37% <50.00%> (ø)`	`30.00 <0.00> (ø)`
...common/table/view/AbstractTableFileSystemView.java	`86.07% <100.00%> (ø)`	`142.00 <0.00> (ø)`
...i/common/table/view/HoodieTableFileSystemView.java	`66.66% <100.00%> (ø)`	`34.00 <1.00> (ø)`
...java/org/apache/hudi/hive/util/HiveSchemaUtil.java	`69.31% <100.00%> (ø)`	`43.00 <0.00> (ø)`
...va/org/apache/hudi/utilities/IdentitySplitter.java	`0.00% <0.00%> (-100.00%)`	`0.00% <0.00%> (-2.00%)`
...va/org/apache/hudi/utilities/schema/SchemaSet.java	`0.00% <0.00%> (-100.00%)`	`0.00% <0.00%> (-3.00%)`
... and 41 more

vinothchandar · 2021-04-19T21:24:37Z

I have re kicked the tests

vinothchandar

Otherwise lgtm

vinothchandar · 2021-05-02T01:06:06Z

Rebased and repushed. Will land once tests pass.

vinothchandar · 2021-05-02T01:06:23Z

@hudi-bot run azure

codecov-commenter · 2021-05-02T01:13:57Z

Codecov Report

Merging #2714 (d1ca93e) into master (bfbf993) will increase coverage by 0.00%.
The diff coverage is 77.77%.

@@            Coverage Diff            @@
##             master    #2714   +/-   ##
=========================================
  Coverage     54.77%   54.77%           
- Complexity     3796     3800    +4     
=========================================
  Files           481      481           
  Lines         23284    23300   +16     
  Branches       2478     2484    +6     
=========================================
+ Hits          12753    12762    +9     
- Misses         9385     9387    +2     
- Partials       1146     1151    +5

Flag	Coverage Δ	Complexity Δ
hudicli	`39.53% <ø> (ø)`	`220.00 <ø> (ø)`
hudiclient	`∅ <ø> (∅)`	`0.00 <ø> (ø)`
hudicommon	`50.37% <100.00%> (-0.02%)`	`1975.00 <1.00> (ø)`
hudiflink	`63.01% <ø> (ø)`	`524.00 <ø> (ø)`
hudihadoopmr	`50.93% <ø> (ø)`	`259.00 <ø> (ø)`
hudisparkdatasource	`73.33% <ø> (ø)`	`237.00 <ø> (ø)`
hudisync	`46.44% <50.00%> (-0.08%)`	`144.00 <0.00> (ø)`
huditimelineservice	`64.36% <50.00%> (ø)`	`62.00 <0.00> (ø)`
hudiutilities	`69.64% <82.35%> (+0.06%)`	`379.00 <4.00> (+4.00)`

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ	Complexity Δ
...java/org/apache/hudi/hive/util/HiveSchemaUtil.java	`68.93% <50.00%> (-0.68%)`	`48.00 <0.00> (ø)`
...g/apache/hudi/timeline/service/RequestHandler.java	`73.37% <50.00%> (ø)`	`30.00 <0.00> (ø)`
...apache/hudi/utilities/deltastreamer/DeltaSync.java	`71.18% <50.00%> (-0.25%)`	`56.00 <0.00> (ø)`
...i/utilities/deltastreamer/HoodieDeltaStreamer.java	`72.44% <85.71%> (+0.65%)`	`22.00 <4.00> (+4.00)`
...di/common/table/timeline/HoodieActiveTimeline.java	`66.81% <100.00%> (ø)`	`43.00 <0.00> (ø)`
...common/table/view/AbstractTableFileSystemView.java	`86.07% <100.00%> (ø)`	`142.00 <0.00> (ø)`
...i/common/table/view/HoodieTableFileSystemView.java	`66.66% <100.00%> (ø)`	`34.00 <1.00> (ø)`
.../utilities/transform/SqlQueryBasedTransformer.java	`75.00% <100.00%> (ø)`	`3.00 <0.00> (ø)`
...e/hudi/common/table/log/HoodieLogFormatWriter.java	`78.12% <0.00%> (-1.57%)`	`26.00% <0.00%> (ø%)`

leesf · 2021-05-02T12:53:32Z

hudi-common/src/main/java/org/apache/hudi/common/table/view/AbstractTableFileSystemView.java


          // Create the path if it does not exist already
          Path partitionPath = FSUtils.getPartitionPath(metaClient.getBasePath(), partitionPathStr);
          FSUtils.createPathIfNotExists(metaClient.getFs(), partitionPath);
          long beginLsTs = System.currentTimeMillis();
          FileStatus[] statuses = listPartition(partitionPath);
          long endLsTs = System.currentTimeMillis();
-          LOG.info("#files found in partition (" + partitionPathStr + ") =" + statuses.length + ", Time taken ="
+          LOG.debug("#files found in partition (" + partitionPathStr + ") =" + statuses.length + ", Time taken ="


this would be info level ? it is helpful to show the time cost.

leesf · 2021-05-02T12:53:47Z

hudi-common/src/main/java/org/apache/hudi/common/table/view/AbstractTableFileSystemView.java

@@ -293,7 +293,7 @@ private void ensurePartitionLoadedCorrectly(String partition) {
        LOG.debug("View already built for Partition :" + partitionPathStr + ", FOUND is ");
      }
      long endTs = System.currentTimeMillis();
-      LOG.info("Time to load partition (" + partitionPathStr + ") =" + (endTs - beginTs));
+      LOG.debug("Time to load partition (" + partitionPathStr + ") =" + (endTs - beginTs));


vburenin · 2021-05-02T14:52:54Z

It is not helpful by any means if there are a few thousands partitions are getting updated every 15 minutes. Dumping aggregated stats would way more useful. Like p50, p95.

…

On Sun, May 2, 2021 at 7:54 AM leesf ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In hudi-common/src/main/java/org/apache/hudi/common/table/view/AbstractTableFileSystemView.java <#2714 (comment)>: > @@ -293,7 +293,7 @@ private void ensurePartitionLoadedCorrectly(String partition) { LOG.debug("View already built for Partition :" + partitionPathStr + ", FOUND is "); } long endTs = System.currentTimeMillis(); - LOG.info("Time to load partition (" + partitionPathStr + ") =" + (endTs - beginTs)); + LOG.debug("Time to load partition (" + partitionPathStr + ") =" + (endTs - beginTs)); ditto — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2714 (review)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABBGHK56VYKTU23WE4O3ZJLTLVDOTANCNFSM4ZXNOKDA> .

vinothchandar · 2021-05-04T00:19:30Z

travis failures seem unrelated, but keeps failing somehow (while other PRs pass). I am going to look at it more closely.

vinothchandar · 2021-05-04T00:21:28Z

@leesf It does make sense to have it in debug for large tables, right? wdyt?

leesf · 2021-05-04T04:04:01Z

@leesf It does make sense to have it in debug for large tables, right? wdyt?

@vinothchandar @vburenin it would be changed to debug if there are some stats to indicate the time cost. I think it is an important stat when profiling.

vinothchandar · 2021-05-06T16:51:46Z

This test is just flaky

[INFO] 
[ERROR] Failures: 
[ERROR]   TestHoodieMultiTableDeltaStreamer.testMultiTableExecutionWithKafkaSource:168 expected: <true> but was: <false>

vinothchandar · 2021-05-06T16:53:46Z

it would be changed to debug if there are some stats to indicate the time cost. I think it is an important stat when profiling.

Typically, we turn on logs with perf profiing only after a dashboard shows some regression right. For e.g in bloom filter code, this is what we do. Keep everything in DEBUG and only turn on as needed. Let me see if I can convince you otherwise :)

vburenin

@leesf It does make sense to have it in debug for large tables, right? wdyt?

@vinothchandar @vburenin it would be changed to debug if there are some stats to indicate the time cost. I think it is an important stat when profiling.

profiling == debugging. I think you want to have such metrics exposed to see these things on your dashboard to monitor them in the first place.

vburenin · 2021-04-04T20:38:04Z

hudi-sync/hudi-hive-sync/src/main/java/org/apache/hudi/hive/util/HiveSchemaUtil.java

@@ -109,7 +109,7 @@ public static SchemaDifference getSchemaDifference(MessageType storageSchema, Ma
        schemaDiffBuilder.addTableColumn(entry.getKey(), entry.getValue());
      }
    }
-    LOG.info("Difference between schemas: " + schemaDiffBuilder.build().toString());
+    LOG.debug("Difference between schemas: " + schemaDiffBuilder.build().toString());


It can be very large some times, that's why I moved it to debug. Schemas on our side are hundreds of pages long. However, if you find it very useful for yourself, I can move it back to info. Just let me know.

vinothchandar

In the interest of moving this forward, made some changes that strike a balance.

vinothchandar · 2021-05-09T02:13:45Z

hudi-common/src/main/java/org/apache/hudi/common/table/timeline/HoodieActiveTimeline.java

@@ -113,7 +113,9 @@ protected HoodieActiveTimeline(HoodieTableMetaClient metaClient, Set<String> inc
    // multiple casts will make this lambda serializable -
    // http://docs.oracle.com/javase/specs/jls/se8/html/jls-15.html#jls-15.16
    this.details = (Function<HoodieInstant, Option<byte[]>> & Serializable) this::getInstantDetails;
-    LOG.info("Loaded instants " + getInstants().collect(Collectors.toList()));
+    if (LOG.isDebugEnabled()) {


This is actually a helpful debug aid, to tell us what the state of the timeline was. So I am changing this to print the last instant , while moving it back to INFO

vinothchandar · 2021-05-09T02:14:02Z

hudi-common/src/main/java/org/apache/hudi/common/table/view/AbstractTableFileSystemView.java

@@ -271,15 +271,15 @@ private void ensurePartitionLoadedCorrectly(String partition) {
      if (!isPartitionAvailableInStore(partitionPathStr)) {
        // Not loaded yet
        try {
-          LOG.info("Building file system view for partition (" + partitionPathStr + ")");
+          LOG.debug("Building file system view for partition (" + partitionPathStr + ")");


this is actually good to keep IMO.

vinothchandar · 2021-05-09T02:49:24Z

hudi-timeline-service/src/main/java/org/apache/hudi/timeline/service/RequestHandler.java

@@ -135,7 +135,7 @@ private boolean syncIfLocalViewBehind(Context ctx) {
      synchronized (view) {
        if (isLocalViewBehind(ctx)) {
          HoodieTimeline localTimeline = viewManager.getFileSystemView(basePath).getTimeline();
-          LOG.info("Syncing view as client passed last known instant " + lastKnownInstantFromClient
+          LOG.debug("Syncing view as client passed last known instant " + lastKnownInstantFromClient


this is again rather important. Going to just have the last instant printed out.

- Fixing flaky multi delta streamer test - Using isDebugEnabled() checks - Some changes to shorten log message without moving to DEBUG

nsivabalan added the code-clean label Mar 30, 2021

pratyakshsharma reviewed Apr 4, 2021

View reviewed changes

vinothchandar added this to Ready For Review in PR Tracker Board Apr 15, 2021

vinothchandar self-assigned this Apr 19, 2021

vinothchandar approved these changes Apr 19, 2021

View reviewed changes

PR Tracker Board automation moved this from Opened PRs to Review in progress Apr 19, 2021

leesf reviewed May 2, 2021

View reviewed changes

vburenin commented May 6, 2021

View reviewed changes

vinothchandar reviewed May 9, 2021

View reviewed changes

volodymyr.burenin and others added 3 commits May 8, 2021 19:59

Reduces log level for too verbose messages from info to debug level.

ae6b58a

Sort config output.

d7f3486

Code Review : Small restructuring + rebasing to master

d1ca93e

- Fixing flaky multi delta streamer test - Using isDebugEnabled() checks - Some changes to shorten log message without moving to DEBUG

vinothchandar merged commit 8a48d16 into apache:master May 10, 2021

PR Tracker Board automation moved this from Review in progress to Done May 10, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[HUDI-1707] Reduces log level for too verbose messages from info to debug level. #2714

[HUDI-1707] Reduces log level for too verbose messages from info to debug level. #2714

vburenin commented Mar 24, 2021

yanghua commented Mar 30, 2021

pratyakshsharma Apr 4, 2021

vburenin Apr 4, 2021

pratyakshsharma commented Apr 4, 2021

vburenin commented Apr 4, 2021

codecov-io commented Apr 4, 2021 •

edited

vinothchandar commented Apr 19, 2021

vinothchandar left a comment

vinothchandar commented May 2, 2021

vinothchandar commented May 2, 2021 •

edited

codecov-commenter commented May 2, 2021 •

edited

leesf May 2, 2021

leesf May 2, 2021

vburenin commented May 2, 2021 via email

vinothchandar commented May 4, 2021

vinothchandar commented May 4, 2021

leesf commented May 4, 2021

vinothchandar commented May 6, 2021

vinothchandar commented May 6, 2021

vburenin left a comment

vburenin Apr 4, 2021

vinothchandar left a comment

vinothchandar May 9, 2021

vinothchandar May 9, 2021

vinothchandar May 9, 2021

[HUDI-1707] Reduces log level for too verbose messages from info to debug level. #2714

[HUDI-1707] Reduces log level for too verbose messages from info to debug level. #2714

Conversation

vburenin commented Mar 24, 2021

What is the purpose of the pull request

Verify this pull request

yanghua commented Mar 30, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pratyakshsharma commented Apr 4, 2021

vburenin commented Apr 4, 2021

codecov-io commented Apr 4, 2021 • edited

Codecov Report

vinothchandar commented Apr 19, 2021

vinothchandar left a comment

Choose a reason for hiding this comment

vinothchandar commented May 2, 2021

vinothchandar commented May 2, 2021 • edited

codecov-commenter commented May 2, 2021 • edited

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vburenin commented May 2, 2021 via email

vinothchandar commented May 4, 2021

vinothchandar commented May 4, 2021

leesf commented May 4, 2021

vinothchandar commented May 6, 2021

vinothchandar commented May 6, 2021

vburenin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vinothchandar left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-io commented Apr 4, 2021 •

edited

vinothchandar commented May 2, 2021 •

edited

codecov-commenter commented May 2, 2021 •

edited