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.

Sign up for GitHub

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

Jump to bottom

[FEATURE] Include hooks in time measurement of blocks #638

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

[FEATURE] Include hooks in time measurement of blocks #638

wants to merge 1 commit into from

Conversation

TungstnBallon
Copy link
Contributor

@TungstnBallon TungstnBallon commented Jan 15, 2025 •
edited
Loading

Closes #637.

This PR adds the hook duration to the debug logger. This is the same level as block duration logging.

@TungstnBallon TungstnBallon self-assigned this Jan 15, 2025
@TungstnBallon TungstnBallon marked this pull request as ready for review January 21, 2025 10:17
@TungstnBallon TungstnBallon requested a review from joluj January 21, 2025 10:17
@joluj
Copy link
Contributor

joluj commented Jan 21, 2025

Could you paste an example output here? Thanks!

@TungstnBallon
Copy link
Contributor Author 

npm run example:cars

> [email protected] example:cars
> nx run interpreter:run -d example/cars.jv -dg peek


> nx run interpreter:run -d example/cars.jv -dg peek

> nx run interpreter:build:development


   ✔  7/7 dependent project tasks succeeded [7 read from cache]

   Hint: you can run the command with --verbose to see the full dependent project outputs

————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————


> nx run interpreter:build:development  [local cache]


————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————————

 NX   Successfully ran target build for project interpreter and 7 tasks it depends on (600ms)

Nx read the output from the cache instead of running the command for 8 out of 8 tasks.

> node --enable-source-maps dist/apps/interpreter/main.js -d example/cars.jv -dg peek

Found 1 pipelines to execute: CarsPipeline
[CarsPipeline] Overview:
        Blocks (6 blocks with 2 pipes):
         -> CarsExtractor (HttpExtractor)
                 -> CarsTextFileInterpreter (TextFileInterpreter)
                         -> CarsCSVInterpreter (CSVInterpreter)
                                 -> NameHeaderWriter (CellWriter)
                                         -> CarsTableInterpreter (TableInterpreter)
                                                 -> CarsLoader (SQLiteLoader)

        [CarsExtractor] Executing general pre-block-hooks
        [CarsExtractor] Executing pre-block-hooks for blocktype HttpExtractor
        [CarsExtractor] pre-block-hooks duration: 1 ms.
        [CarsExtractor] Fetching raw data from https://gist.githubusercontent.com/noamross/e5d3e859aa0c794be10b/raw/b999fb4425b54c63cab088c0ce2c0d6ce961a563/cars.csv
        [CarsExtractor] Successfully fetched raw data
        [CarsExtractor] [Output] <hex> 22222C226D7067222C2263796C222C2264697370222C226870222C2264726174222C227774222C2271736563222C227673222C22616D222C2267656172222C2263617262220A224D617A646120525834222C32312C362C3136302C3131302C332E392C32
        [CarsExtractor] [Output] ... (omitted in peek mode)
        [CarsExtractor] Block duration: 209 ms.
        [CarsExtractor] Executing general post-block-hooks
        [CarsExtractor] Executing post-block-hooks for blocktype HttpExtractor
        [CarsExtractor] post-block-hooks duration: 1 ms.
        [CarsExtractor] Total duration: 212 ms.
        [CarsTextFileInterpreter] Executing general pre-block-hooks
        [CarsTextFileInterpreter] Executing pre-block-hooks for blocktype TextFileInterpreter
        [CarsTextFileInterpreter] pre-block-hooks duration: 1 ms.
        [CarsTextFileInterpreter] Decoding file content using encoding "utf-8"
        [CarsTextFileInterpreter] Splitting lines using line break /\r?\n/
        [CarsTextFileInterpreter] Lines were split successfully, the resulting text file has 33 lines
        [CarsTextFileInterpreter] [Output] [Line 0] "","mpg","cyl","disp","hp","drat","wt","qsec","vs","am","gear","carb"
        [CarsTextFileInterpreter] [Output] [Line 1] "Mazda RX4",21,6,160,110,3.9,2.62,16.46,0,1,4,4
        [CarsTextFileInterpreter] [Output] [Line 2] "Mazda RX4 Wag",21,6,160,110,3.9,2.875,17.02,0,1,4,4
        [CarsTextFileInterpreter] [Output] [Line 3] "Datsun 710",22.8,4,108,93,3.85,2.32,18.61,1,1,4,1
        [CarsTextFileInterpreter] [Output] [Line 4] "Hornet 4 Drive",21.4,6,258,110,3.08,3.215,19.44,1,0,3,1
        [CarsTextFileInterpreter] [Output] [Line 5] "Hornet Sportabout",18.7,8,360,175,3.15,3.44,17.02,0,0,3,2
        [CarsTextFileInterpreter] [Output] [Line 6] "Valiant",18.1,6,225,105,2.76,3.46,20.22,1,0,3,1
        [CarsTextFileInterpreter] [Output] [Line 7] "Duster 360",14.3,8,360,245,3.21,3.57,15.84,0,0,3,4
        [CarsTextFileInterpreter] [Output] [Line 8] "Merc 240D",24.4,4,146.7,62,3.69,3.19,20,1,0,4,2
        [CarsTextFileInterpreter] [Output] [Line 9] "Merc 230",22.8,4,140.8,95,3.92,3.15,22.9,1,0,4,2
        [CarsTextFileInterpreter] [Output] [Line 10] "Merc 280",19.2,6,167.6,123,3.92,3.44,18.3,1,0,4,4
        [CarsTextFileInterpreter] [Output] ... (omitted in peek mode)
        [CarsTextFileInterpreter] Block duration: 0 ms.
        [CarsTextFileInterpreter] Executing general post-block-hooks
        [CarsTextFileInterpreter] Executing post-block-hooks for blocktype TextFileInterpreter
        [CarsTextFileInterpreter] post-block-hooks duration: 1 ms.
        [CarsTextFileInterpreter] Total duration: 2 ms.
        [CarsCSVInterpreter] Executing general pre-block-hooks
        [CarsCSVInterpreter] Executing pre-block-hooks for blocktype CSVInterpreter
        [CarsCSVInterpreter] pre-block-hooks duration: 1 ms.
        [CarsCSVInterpreter] Parsing raw data as CSV using delimiter ","
        [CarsCSVInterpreter] Parsing raw data as CSV-sheet successful
        [CarsCSVInterpreter] [Output] Sheet with 33 rows and 12 columns.
        [CarsCSVInterpreter] [Output] [Row 0] "", "mpg", "cyl", "disp", "hp", "drat", "wt", "qsec", "vs", "am", "gear", "carb"
        [CarsCSVInterpreter] [Output] [Row 1] "Mazda RX4", "21", "6", "160", "110", "3.9", "2.62", "16.46", "0", "1", "4", "4"
        [CarsCSVInterpreter] [Output] [Row 2] "Mazda RX4 Wag", "21", "6", "160", "110", "3.9", "2.875", "17.02", "0", "1", "4", "4"
        [CarsCSVInterpreter] [Output] [Row 3] "Datsun 710", "22.8", "4", "108", "93", "3.85", "2.32", "18.61", "1", "1", "4", "1"
        [CarsCSVInterpreter] [Output] [Row 4] "Hornet 4 Drive", "21.4", "6", "258", "110", "3.08", "3.215", "19.44", "1", "0", "3", "1"
        [CarsCSVInterpreter] [Output] [Row 5] "Hornet Sportabout", "18.7", "8", "360", "175", "3.15", "3.44", "17.02", "0", "0", "3", "2"
        [CarsCSVInterpreter] [Output] [Row 6] "Valiant", "18.1", "6", "225", "105", "2.76", "3.46", "20.22", "1", "0", "3", "1"
        [CarsCSVInterpreter] [Output] [Row 7] "Duster 360", "14.3", "8", "360", "245", "3.21", "3.57", "15.84", "0", "0", "3", "4"
        [CarsCSVInterpreter] [Output] [Row 8] "Merc 240D", "24.4", "4", "146.7", "62", "3.69", "3.19", "20", "1", "0", "4", "2"
        [CarsCSVInterpreter] [Output] [Row 9] "Merc 230", "22.8", "4", "140.8", "95", "3.92", "3.15", "22.9", "1", "0", "4", "2"
        [CarsCSVInterpreter] [Output] ... (omitted in peek mode)
        [CarsCSVInterpreter] Block duration: 10 ms.
        [CarsCSVInterpreter] Executing general post-block-hooks
        [CarsCSVInterpreter] Executing post-block-hooks for blocktype CSVInterpreter
        [CarsCSVInterpreter] post-block-hooks duration: 0 ms.
        [CarsCSVInterpreter] Total duration: 11 ms.
        [NameHeaderWriter] Executing general pre-block-hooks
        [NameHeaderWriter] Executing pre-block-hooks for blocktype CellWriter
        [NameHeaderWriter] pre-block-hooks duration: 1 ms.
        [NameHeaderWriter] Writing "name" at cell A1
        [NameHeaderWriter] [Output] Sheet with 33 rows and 12 columns.
        [NameHeaderWriter] [Output] [Row 0] "name", "mpg", "cyl", "disp", "hp", "drat", "wt", "qsec", "vs", "am", "gear", "carb"
        [NameHeaderWriter] [Output] [Row 1] "Mazda RX4", "21", "6", "160", "110", "3.9", "2.62", "16.46", "0", "1", "4", "4"
        [NameHeaderWriter] [Output] [Row 2] "Mazda RX4 Wag", "21", "6", "160", "110", "3.9", "2.875", "17.02", "0", "1", "4", "4"
        [NameHeaderWriter] [Output] [Row 3] "Datsun 710", "22.8", "4", "108", "93", "3.85", "2.32", "18.61", "1", "1", "4", "1"
        [NameHeaderWriter] [Output] [Row 4] "Hornet 4 Drive", "21.4", "6", "258", "110", "3.08", "3.215", "19.44", "1", "0", "3", "1"
        [NameHeaderWriter] [Output] [Row 5] "Hornet Sportabout", "18.7", "8", "360", "175", "3.15", "3.44", "17.02", "0", "0", "3", "2"
        [NameHeaderWriter] [Output] [Row 6] "Valiant", "18.1", "6", "225", "105", "2.76", "3.46", "20.22", "1", "0", "3", "1"
        [NameHeaderWriter] [Output] [Row 7] "Duster 360", "14.3", "8", "360", "245", "3.21", "3.57", "15.84", "0", "0", "3", "4"
        [NameHeaderWriter] [Output] [Row 8] "Merc 240D", "24.4", "4", "146.7", "62", "3.69", "3.19", "20", "1", "0", "4", "2"
        [NameHeaderWriter] [Output] [Row 9] "Merc 230", "22.8", "4", "140.8", "95", "3.92", "3.15", "22.9", "1", "0", "4", "2"
        [NameHeaderWriter] [Output] ... (omitted in peek mode)
        [NameHeaderWriter] Block duration: 0 ms.
        [NameHeaderWriter] Executing general post-block-hooks
        [NameHeaderWriter] Executing post-block-hooks for blocktype CellWriter
        [NameHeaderWriter] post-block-hooks duration: 1 ms.
        [NameHeaderWriter] Total duration: 2 ms.
        [CarsTableInterpreter] Executing general pre-block-hooks
        [CarsTableInterpreter] Executing pre-block-hooks for blocktype TableInterpreter
        [CarsTableInterpreter] pre-block-hooks duration: 0 ms.
        [CarsTableInterpreter] Matching header with provided column names
        [CarsTableInterpreter] Validating 32 row(s) according to the column types
        [CarsTableInterpreter] Validation completed, the resulting table has 32 row(s) and 12 column(s)
        [CarsTableInterpreter] [Output] Table with 32 rows and 12 columns.
        [CarsTableInterpreter] [Output] [Header] name (text) | mpg (decimal) | cyl (integer) | disp (decimal) | hp (integer) | drat (decimal) | wt (decimal) | qsec (decimal) | vs (integer) | am (integer) | gear (integer) | carb (integer)
        [CarsTableInterpreter] [Output] [Row 0] "Mazda RX4" | 21 | 6 | 160 | 110 | 3.9 | 2.62 | 16.46 | 0 | 1 | 4 | 4
        [CarsTableInterpreter] [Output] [Row 1] "Mazda RX4 Wag" | 21 | 6 | 160 | 110 | 3.9 | 2.875 | 17.02 | 0 | 1 | 4 | 4
        [CarsTableInterpreter] [Output] [Row 2] "Datsun 710" | 22.8 | 4 | 108 | 93 | 3.85 | 2.32 | 18.61 | 1 | 1 | 4 | 1
        [CarsTableInterpreter] [Output] [Row 3] "Hornet 4 Drive" | 21.4 | 6 | 258 | 110 | 3.08 | 3.215 | 19.44 | 1 | 0 | 3 | 1
        [CarsTableInterpreter] [Output] [Row 4] "Hornet Sportabout" | 18.7 | 8 | 360 | 175 | 3.15 | 3.44 | 17.02 | 0 | 0 | 3 | 2
        [CarsTableInterpreter] [Output] [Row 5] "Valiant" | 18.1 | 6 | 225 | 105 | 2.76 | 3.46 | 20.22 | 1 | 0 | 3 | 1
        [CarsTableInterpreter] [Output] [Row 6] "Duster 360" | 14.3 | 8 | 360 | 245 | 3.21 | 3.57 | 15.84 | 0 | 0 | 3 | 4
        [CarsTableInterpreter] [Output] [Row 7] "Merc 240D" | 24.4 | 4 | 146.7 | 62 | 3.69 | 3.19 | 20 | 1 | 0 | 4 | 2
        [CarsTableInterpreter] [Output] [Row 8] "Merc 230" | 22.8 | 4 | 140.8 | 95 | 3.92 | 3.15 | 22.9 | 1 | 0 | 4 | 2
        [CarsTableInterpreter] [Output] [Row 9] "Merc 280" | 19.2 | 6 | 167.6 | 123 | 3.92 | 3.44 | 18.3 | 1 | 0 | 4 | 4
        [CarsTableInterpreter] [Output] ... (omitted in peek mode)
        [CarsTableInterpreter] Block duration: 2 ms.
        [CarsTableInterpreter] Executing general post-block-hooks
        [CarsTableInterpreter] Executing post-block-hooks for blocktype TableInterpreter
        [CarsTableInterpreter] post-block-hooks duration: 1 ms.
        [CarsTableInterpreter] Total duration: 3 ms.
        [CarsLoader] Executing general pre-block-hooks
        [CarsLoader] Executing pre-block-hooks for blocktype SQLiteLoader
        [CarsLoader] pre-block-hooks duration: 0 ms.
        [CarsLoader] Opening database file ./cars.sqlite
        [CarsLoader] Dropping previous table "Cars" if it exists
        [CarsLoader] Creating table "Cars"
        [CarsLoader] Inserting 32 row(s) into table "Cars"
        [CarsLoader] The data was successfully loaded into the database
        [CarsLoader] [Output] <None>
        [CarsLoader] Block duration: 83 ms.
        [CarsLoader] Executing general post-block-hooks
        [CarsLoader] Executing post-block-hooks for blocktype SQLiteLoader
        [CarsLoader] post-block-hooks duration: 1 ms.
        [CarsLoader] Total duration: 84 ms.
[CarsPipeline] Execution duration: 314 ms.

@joluj

@TungstnBallon TungstnBallon mentioned this pull request Jan 21, 2025
Draft
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@joluj joluj Awaiting requested review from joluj

Assignees

@TungstnBallon TungstnBallon

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

[FEATURE] Include hooks in time measurement of blocks
2 participants
@TungstnBallon @joluj