Repository navigation
Better Debugging: Terminal Output illustrates the sequence of events in plainer terms #3096
Description
Alight, the scope of this has changed given most people won't want to reach for another flag to understand what SQLMesh is doing behind the scenes when it's running.
This issue is better framed as improving the understandability of what applying a plan does with an easy way to debug as needed to verify understanding.
Current State Plan Output
Creating physical tables ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 3/3 • 0:00:03
Model versions created successfully
[1/1] demo__dev_sung.stg_payments evaluated in 4.15s
[1/1] demo__dev_sung.orders evaluated in 4.85s
[1/1] demo__dev_sung.customers evaluated in 4.93s
Evaluating models ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 3/3 • 0:00:09
Model batches executed successfully
Virtually Updating 'dev_sung' ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 0:00:02
Target environment updated successfullyFuture State Draft Plan Output
- I parse out exactly what each progress bar is doing per model
- Rename the first progress bar to "physical layer" as that's more accurate
- explain what it actually did: recreated view, audits pass, merged N rows, etc.
- list out versioned objects and the final virtual update objects so it's easy to copy/paste to search in the logs
- Added a quick summary at the end to feel the full impact of the applied plan
- Easy relative link to cmd+click into the logs in the IDE
- When this is running in progress (I don't visualize here), the
demo__dev_sung.full_model...format is fine because we explain what happened after the...is finished and it's nested under a relevant progress bar.
Creating physical layer ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 3/3 • 0:00:03
[1/1] demo__dev_sung.stg_payments evaluated[recreated view] in 1s
sqlmesh-public-demo.demo__dev_sung.stg_payments_1293197
[1/1] demo__dev_sung.orders evaluated[created empty table] in 1s
sqlmesh-public-demo.demo__dev_sung.orders_11978257
[1/1] demo__dev_sung.customers evaluated[cloned table] in 1s
??? TBD as this gets dropped later
Model versions created successfully
Evaluating models ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 3/3 • 0:00:09
[1/1] demo__dev_sung.stg_payments evaluated[audits pass] in 4.15s
[1/1] demo__dev_sung.orders evaluated[fully refreshed, audits pass] in 4.85s
[1/1] demo__dev_sung.customers evaluated[merged 100 rows, audits pass] in 4.93s
Model batches executed successfully
Virtually Updating 'dev_sung' ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100.0% • 0:00:02
sqlmesh-public-demo.demo__dev_sung.stg_payments
sqlmesh-public-demo.demo__dev_sung.orders
sqlmesh-public-demo.demo__dev_sung.customers
Target environment updated successfully
Plan applied for 1 VIEW model, 1 FULL model, 1 INCREMENTAL_BY_TIME_RANGE model, 3 audits in 9s.
View Logs: logs/sqlmesh_2025_01_30_10_24_47.logThis coincides with the work you've been doing @treysp
Activity
giovannipcarvalho commentedon Sep 10, 2024
Related #1254?
sungchun12 commentedon Sep 14, 2024
This would also be helpful as debug logs while the
sqlmesh runorsqlmesh plancommand is running so it's clear where the sqlmesh steps failed as getting a query engine specific error message doesn't immediately tell me where it failed. This will also build clarity when "physical tables are being created" for views which don't have any physical data so people don't get confused in the terminal when they see that progress bar.sungchun12 commentedon Jan 30, 2025
For reference, I want code snippets paired with easy to understand explanations: https://sqlmesh.readthedocs.io/en/stable/examples/incremental_time_full_walkthrough/#setup
[-]Better Debugging: Pretty SQL Rendering for dry runs in terminal[/-][+]Better Debugging: Terminal Output illustrates the sequence of events in plainer terms[/+]