Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue 288: Add log messages #289

Merged
merged 8 commits into from
Apr 4, 2024
Merged

Conversation

fpj
Copy link
Contributor

@fpj fpj commented Mar 22, 2024

Description

It adds log messages to be able to trace activity when executing such as the following:

spark_data.write.format("qbeast")
            .mode("append")
            .options(**qbeast_options)
            .save(output_path)

The code at the moment is very scarce on log messages, in factr, I couldn't find any in the part of the code I was inspecting. It is going to take multiple PRs to populate the code base with logging messages appropriately.

Fixes #288

Type of change

It is adding log messages using the spark internal logging trait. As such, we have to add a line to specific classes to have them using org.apache.spark.internal.Logging.

In the log messages I added so far, I have prefixed it with Qbeast: to make it easier to locate the messages among all INFO messages that Spark generated. That's not ideal, and I'd much rather have the logs printing the fully-qualified class name. We might want to change it before merging.

Checklist:

Here is the list of things you should do before submitting this pull request:

  • Your branch is updated to the main branch (dependent changes have been merged).

How Has This Been Tested? (Optional)

I have validated locally with spark-shell that the messages are printing.

Test Configuration:

  • Spark Version: 3.5.0
  • Hadoop Version:
  • Cluster or local? Local

@fpj fpj requested a review from osopardo1 March 22, 2024 17:36
Copy link

codecov bot commented Mar 23, 2024

Codecov Report

Attention: Patch coverage is 95.83333% with 1 lines in your changes are missing coverage. Please review.

Project coverage is 90.77%. Comparing base (277b170) to head (f3b476f).
Report is 1 commits behind head on main.

Files Patch % Lines
...ala/io/qbeast/spark/delta/writer/BlockWriter.scala 66.66% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main     #289      +/-   ##
==========================================
- Coverage   90.78%   90.77%   -0.01%     
==========================================
  Files          98       98              
  Lines        2604     2623      +19     
  Branches      346      336      -10     
==========================================
+ Hits         2364     2381      +17     
- Misses        240      242       +2     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@fpj
Copy link
Contributor Author

fpj commented Mar 26, 2024

With the recent commit, the output looks like this:

24/03/26 12:29:53 INFO QbeastDataSource: Getting Qbeast table /path/nyc-qbeast-table
24/03/26 12:29:53 TRACE QbeastDataSource: Start: Create Qbeast relation /path/nyc-qbeast-table
24/03/26 12:29:53 TRACE IndexedTableImpl: Start: save table /path/nyc-qbeast-table
24/03/26 12:29:53 TRACE IndexedTableImpl: Begin: Writing data to table /path/nyc-qbeast-table
24/03/26 12:29:53 DEBUG IndexedTableImpl: Writing data to table /path/nyc-qbeast-table, with revision 0
24/03/26 12:29:53 TRACE IndexedTableImpl: Begin: Writing data to table /path/nyc-qbeast-table
24/03/26 12:29:53 TRACE SparkOTreeManager: Begin: index with revision Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:29:53 TRACE DoublePassOTreeDataAnalyzer: Begin: analyze for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:29:54 DEBUG DoublePassOTreeDataAnalyzer: Computing partition-level cube domains for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector()), Revision(1,1711452594393,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector(LinearTransformation(-750.0,386983.63,198550.18258925626,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformation(0.0,185250.45,46861.16844627305,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@1a4589e9))), false
24/03/26 12:29:54 DEBUG DoublePassOTreeDataAnalyzer: Computing global cube domains for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:30:05 DEBUG DoublePassOTreeDataAnalyzer: Merging global cube domains for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:30:05 DEBUG DoublePassOTreeDataAnalyzer: Estimating cube weights for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector()), false
24/03/26 12:30:05 TRACE DoublePassOTreeDataAnalyzer: End: analyze for index Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:30:05 TRACE SparkOTreeManager: End: index with revision Revision(0,1711452593440,/path/nyc-qbeast-table,50000,Vector(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6821f91b), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@1a4589e9)),Vector())
24/03/26 12:30:20 WARN SparkStringUtils: Truncated the string representation of a plan since it was too large. This behavior can be adjusted by setting 'spark.sql.debug.maxToStringFields'.
24/03/26 12:30:21 TRACE IndexedTableImpl: End: Writing data to table /path/nyc-qbeast-table
24/03/26 12:30:21 TRACE IndexedTableImpl: End: Done writing data to table /path/nyc-qbeast-table
24/03/26 12:30:21 TRACE IndexedTableImpl: Done: save table /path/nyc-qbeast-table
24/03/26 12:30:21 TRACE QbeastDataSource: End: Create Qbeast relation /path/nyc-qbeast-table

Note that I have configured log4j to only output Qbeast log messages with severity level TRACE, the severity level for Spark remains as WARN.

@fpj fpj requested a review from Jiaweihu08 March 26, 2024 11:40
@fpj fpj changed the base branch from main-1.0.0 to main April 2, 2024 17:05
@fpj fpj changed the base branch from main to main-1.0.0 April 2, 2024 17:05
@fpj fpj force-pushed the 288-add-log-messages branch from ccee887 to 5c3311b Compare April 2, 2024 18:22
@fpj fpj changed the base branch from main-1.0.0 to main April 2, 2024 18:22
Copy link
Member

@osopardo1 osopardo1 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changes look good to me!

Just a couple of comments, and some questions:

  • I want to understand a bit more the criteria to print the message in INFO, DEBUG or TRACE.
  • Should the logging be tested?

Thanks 😄

Copy link
Contributor Author

@fpj fpj left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the comments, @osopardo1 . Check my responses when you have a chance, pls.

@fpj
Copy link
Contributor Author

fpj commented Apr 3, 2024

On the questions you asked earlier:

I want to understand a bit more the criteria to print the message in INFO, DEBUG or TRACE.

Roughly how I use them:

  • WARN level is supposed to be critical and actionable. If the user sees a WARN, then something bad happened and it might require user intervention.
  • INFO level provides information about the execution, but not necessarily actionable and it avoids being verbose. It is not uncommon to see INFO level on in production, so it is expected to be lightweight with respect to the volume of messages generated.
  • DEBUG provides debug level info when debugging the code. It can be verbose as it is not expected to be on in production.
  • TRACE provides further detail to DEBUG on execution paths, and in particular, it indicates critical the methods that been executed. I like the idea of having begin and end messages so that we see when a method begins and ends.

We should consider having more formal definitions with examples as part of contribution guidelines.

Should the logging be tested?

It is a good point. If the code path where the log message lies is being executed, then the corresponding log method (logDebug, logInfo) is also being executed. But, it is accurate that a test case is not necessarily going to spot whether a message is not useful for a human being or even some automation software that processes logs. If there are downstream systems consuming such logs, then we could consider having integration tests to validate the messages.

@osopardo1
Copy link
Member

On the questions you asked earlier:

I want to understand a bit more the criteria to print the message in INFO, DEBUG or TRACE.

Roughly how I use them:

  • WARN level is supposed to be critical and actionable. If the user sees a WARN, then something bad happened and it might require user intervention.
  • INFO level provides information about the execution, but not necessarily actionable and it avoids being verbose. It is not uncommon to see INFO level on in production, so it is expected to be lightweight with respect to the volume of messages generated.
  • DEBUG provides debug level info when debugging the code. It can be verbose as it is not expected to be on in production.
  • TRACE provides further detail to DEBUG on execution paths, and in particular, it indicates critical the methods that been executed. I like the idea of having begin and end messages so that we see when a method begins and ends.

We should consider having more formal definitions with examples as part of contribution guidelines.

Should the logging be tested?

It is a good point. If the code path where the log message lies is being executed, then the corresponding log method (logDebug, logInfo) is also being executed. But, it is accurate that a test case is not necessarily going to spot whether a message is not useful for a human being or even some automation software that processes logs. If there are downstream systems consuming such logs, then we could consider having integration tests to validate the messages.

Got it! Let me write the first point into an issue.

The test reasoning seems good to me. But now seems like Codecov is not executing those lines... I don't know what is the problem exactly, I am not able to detect a pattern (if it's not printing trace or debug...) and the other parts of the code are being tested as well. Do you know what can be?

@osopardo1
Copy link
Member

Aside from Codecov complains, the PR LGTM 🙌

@osopardo1 osopardo1 self-requested a review April 4, 2024 06:37
@fpj
Copy link
Contributor Author

fpj commented Apr 4, 2024

@osopardo1 here is a sample output:

24/04/04 13:24:32 INFO QbeastDataSource: Getting Qbeast table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:24:32 DEBUG QbeastDataSource: Table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch properties: Map(cubeSize -> 50000, path -> /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch, columnsToIndex -> fare_amount,trip_distance,passenger_count)
24/04/04 13:24:32 TRACE QbeastDataSource: Begin: Create Qbeast relation /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:24:32 TRACE IndexedTableImpl: Begin: save table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:24:32 DEBUG IndexedTableImpl: Appending data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch with revision=4
24/04/04 13:24:32 DEBUG IndexedTableImpl: Loading latest revision for table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch with revision=4
24/04/04 13:24:33 TRACE IndexedTableImpl: Begin: Writing data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:24:33 DEBUG IndexedTableImpl: Writing data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch with revision 4
24/04/04 13:24:33 TRACE IndexedTableImpl: Begin: Writing data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:24:33 TRACE SparkOTreeManager: Begin: index with revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:24:33 TRACE DoublePassOTreeDataAnalyzer: Begin: analyze for index with revision=Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61))) and isReplication=false
24/04/04 13:24:33 DEBUG DoublePassOTreeDataAnalyzer: newRevision=Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:24:33 DEBUG DoublePassOTreeDataAnalyzer: Computing global cube domains for index revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:24:33 WARN DAGScheduler: Broadcasting large task binary with size 1505.5 KiB
24/04/04 13:25:05 WARN DAGScheduler: Broadcasting large task binary with size 1521.6 KiB
24/04/04 13:25:05 DEBUG DoublePassOTreeDataAnalyzer: Merging global cube domains for index revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:25:05 DEBUG DoublePassOTreeDataAnalyzer: Estimating cube weights for index revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:25:05 TRACE DoublePassOTreeDataAnalyzer: End: analyze for index with revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:25:05 TRACE SparkOTreeManager: End: index with revision Revision(4,1711452971649,/Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch,50000,List(LinearTransformer(fare_amount,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(trip_distance,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformer(passenger_count,io.qbeast.core.model.LongDataType$@39262d61)),List(LinearTransformation(-1.33391414E8,401092.32,-8.769787799728292E7,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0.0,389678.46,56776.69812021143,io.qbeast.core.model.DoubleDataType$@6f5866ec), LinearTransformation(0,9,7,io.qbeast.core.model.LongDataType$@39262d61)))
24/04/04 13:25:41 TRACE IndexedTableImpl: End: Writing data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:25:41 TRACE IndexedTableImpl: End: Done writing data to table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:25:41 TRACE IndexedTableImpl: End: save table /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch
24/04/04 13:25:41 TRACE QbeastDataSource: End: Create Qbeast relation /Users/fpj/tmp/test-data/nyc-qbeast-table-2nd-batch

For this command:

dfCasted.write.format("qbeast").mode("append").
                                        option("columnsToIndex", "fare_amount,trip_distance,passenger_count").
                                        option("cubeSize", "50000").
                                        save("/path/nyc-qbeast-table")

@osopardo1 osopardo1 merged commit 5ac4865 into Qbeast-io:main Apr 4, 2024
3 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add Log Messages with SLF4J
2 participants