search

facebookincubator / velox

A composable and fully extensible C++ execution engine library for data management systems.
https://velox-lib.io/
Apache License 2.0
3.54k stars 1.17k forks source link

TPC-H Q21 wrong results with SF10 #4312

Open lawben opened 1 year ago

lawben commented 1 year ago

Bug description

While benchmarking TPC-H with Parquet input, I came across weird performance numbers for Q21 with SF10. When looking into it, I found out that the results are incorrect.

In the lowest TableScan in the logs below, we only have "Raw Input: 3229839 rows", which is only 5% of the data. At SF10, we have ~60 million rows in lineitem.

For comparison, I also ran this Q21 with DuckDB on the same Parquet files, and get other results. See logs below for DuckDB output. Basically, the main difference can be seen in the first 5 rows of the output (data is sorted by the aggregation value DESC):

Velox DuckDB
{Supplier#000006996, 4} Supplier#000062538, 24
{Supplier#000014765, 4} Supplier#000032858, 22
{Supplier#000028496, 4} Supplier#000063723, 21
{Supplier#000033080, 4} Supplier#000089484, 21
{Supplier#000034162, 4} Supplier#000007061, 20
... ...

For SF1, Velox and DuckDB produce the same results.

I also encountered this issue on my M1 dev machine.

System information

Velox System Info v0.0.2 Commit: 0e230792d9fb681e9756954eef1bf8dc0a87c10f CMake Version: 3.22.1 System: Linux-5.15.0-58-generic Arch: x86_64 C++ Compiler: /usr/bin/clang++-15 C++ Compiler Version: 15.0.6 C Compiler:/usr/bin/clang-15 C Compiler Version: 15.0.6 CMake Prefix Path: /usr/local;/usr;/;/usr;/usr/local;/usr/X11R6;/usr/pkg;/opt

Relevant logs

These are the results for Velox run with:
./velox/benchmarks/tpch/velox_tpch_benchmark --data_path=tpch-sf10 --run_query_verbose=21 --include_results=True

--------------------
E0316 14:11:53.142491 3224929 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.142552 3224926 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.142556 3224928 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.142556 3224927 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.150594 3224922 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.150596 3224908 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.150596 3224924 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.150636 3224921 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420439 3224937 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420439 3224930 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420445 3224936 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420439 3224935 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420439 3224931 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.420439 3224934 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.438588 3224933 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.438588 3224932 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.439157 3224924 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.440778 3224921 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.727751 3224936 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
E0316 14:11:53.728096 3224937 Exceptions.h:68] Line: /velox-main/velox/type/Type.cpp:356, Function:getChildIdx, Expression:  Field not found: l_commitdate. Available fields are: ., Source: USER, ErrorCode: INVALID_ARGUMENT
Results:
ROW<s_name:VARCHAR,numwait:BIGINT>
{Supplier#000006996, 4}
{Supplier#000014765, 4}
{Supplier#000028496, 4}
{Supplier#000033080, 4}
{Supplier#000034162, 4}
{Supplier#000039756, 4}
{Supplier#000043746, 4}
{Supplier#000044991, 4}
{Supplier#000058214, 4}
{Supplier#000062410, 4}
{Supplier#000066043, 4}
{Supplier#000085820, 4}
{Supplier#000093021, 4}
{Supplier#000000496, 3}
{Supplier#000000659, 3}
{Supplier#000002717, 3}
{Supplier#000010487, 3}
{Supplier#000011320, 3}
{Supplier#000021888, 3}
{Supplier#000021946, 3}
{Supplier#000022924, 3}
{Supplier#000024675, 3}
{Supplier#000024973, 3}
{Supplier#000025656, 3}
{Supplier#000026555, 3}
{Supplier#000028002, 3}
{Supplier#000029424, 3}
{Supplier#000031248, 3}
{Supplier#000036884, 3}
{Supplier#000037030, 3}
{Supplier#000038187, 3}
{Supplier#000039333, 3}
{Supplier#000040146, 3}
{Supplier#000041178, 3}
{Supplier#000042132, 3}
{Supplier#000047980, 3}
....  /// some more lines here

Execution time: 1.38s
Splits total: 60, finished: 60
-- Limit[100] -> s_name:VARCHAR, numwait:BIGINT
   Output: 100 rows (96.28KB, 1 batches), Cpu time: 5.22us, Blocked wall time: 0ns, Peak memory: 0B, Memory allocations: 0, Threads: 1
  -- OrderBy[numwait DESC NULLS LAST, s_name ASC NULLS LAST] -> s_name:VARCHAR, numwait:BIGINT
     Output: 1649 rows (96.28KB, 1 batches), Cpu time: 255.90us, Blocked wall time: 0ns, Peak memory: 1.00MB, Memory allocations: 7, Threads: 1
    -- Aggregation[FINAL [s_name] numwait := count("numwait")] -> s_name:VARCHAR, numwait:BIGINT
       Output: 1649 rows (167.69KB, 2 batches), Cpu time: 1.43ms, Blocked wall time: 0ns, Peak memory: 1.00MB, Memory allocations: 10, Threads: 1
      -- LocalPartition[GATHER] -> s_name:VARCHAR, numwait:BIGINT
         Output: 3298 rows (335.38KB, 2 batches), Cpu time: 79.05us, Blocked wall time: 9.04s, Peak memory: 0B, Memory allocations: 0
         LocalPartition: Input: 1649 rows (167.69KB, 2 batches), Output: 1649 rows (167.69KB, 0 batches), Cpu time: 44.45us, Blocked wall time: 5.77s, Peak memory: 0B, Memory allocations: 0, Threads: 4
         LocalExchange: Input: 1649 rows (167.69KB, 0 batches), Output: 1649 rows (167.69KB, 2 batches), Cpu time: 34.59us, Blocked wall time: 3.27s, Peak memory: 0B, Memory allocations: 0, Threads: 1
        -- Aggregation[PARTIAL [s_name] numwait := count(1)] -> s_name:VARCHAR, numwait:BIGINT
           Output: 1649 rows (167.69KB, 2 batches), Cpu time: 2.12ms, Blocked wall time: 0ns, Peak memory: 1.00MB, Memory allocations: 22, Threads: 4
          -- HashJoin[ANTI l_orderkey_1=l_orderkey_3, filter: neq(ROW["l_suppkey_3"],ROW["l_suppkey_1"]), null aware] -> s_name:VARCHAR
             Output: 2123 rows (152.62KB, 149 batches), Cpu time: 2.06s, Blocked wall time: 3.99s, Peak memory: 57.00MB, Memory allocations: 1460913
             HashBuild: Input: 2041267 rows (38.32MB, 362 batches), Output: 0 rows (0B, 0 batches), Cpu time: 171.15ms, Blocked wall time: 580.86ms, Peak memory: 56.00MB, Memory allocations: 1035, Threads: 4
             HashProbe: Input: 37998 rows (3.55MB, 38 batches), Output: 2123 rows (152.62KB, 149 batches), Cpu time: 1.89s, Blocked wall time: 3.41s, Peak memory: 1.00MB, Memory allocations: 1459878, Threads: 4
            -- HashJoin[RIGHT SEMI (FILTER) l_orderkey_2=l_orderkey_1, filter: neq(ROW["l_suppkey_2"],ROW["l_suppkey_1"])] -> l_orderkey_1:BIGINT, l_suppkey_1:BIGINT, s_name:VARCHAR
               Output: 37998 rows (3.55MB, 38 batches), Cpu time: 22.52ms, Blocked wall time: 348.74ms, Peak memory: 5.00MB, Memory allocations: 621
               HashBuild: Input: 39475 rows (6.16MB, 81 batches), Output: 0 rows (0B, 0 batches), Cpu time: 7.71ms, Blocked wall time: 30.62ms, Peak memory: 4.00MB, Memory allocations: 52, Threads: 4
               HashProbe: Input: 186215 rows (32.13MB, 350 batches), Output: 37998 rows (3.55MB, 38 batches), Cpu time: 14.81ms, Blocked wall time: 318.12ms, Peak memory: 1.00MB, Memory allocations: 569, Threads: 4
              -- Project[expressions: (l_orderkey_2:BIGINT, ROW["l_orderkey"]), (l_suppkey_2:BIGINT, ROW["l_suppkey"])] -> l_orderkey_2:BIGINT, l_suppkey_2:BIGINT
                 Output: 186215 rows (32.13MB, 350 batches), Cpu time: 662.14us, Blocked wall time: 0ns, Peak memory: 0B, Memory allocations: 0, Threads: 4
                -- TableScan[table: lineitem] -> l_suppkey:BIGINT, l_orderkey:BIGINT
                   Input: 186215 rows (32.13MB, 0 batches), Raw Input: 3229839 rows (178.98MB), Output: 186215 rows (32.13MB, 350 batches), Cpu time: 1.20s, Blocked wall time: 0ns, Peak memory: 64.00MB, Memory allocations: 2560, Threads: 4, Splits: 10
              -- HashJoin[INNER o_orderkey=l_orderkey_1] -> s_nationkey:BIGINT, l_orderkey_1:BIGINT, l_suppkey_1:BIGINT, s_name:VARCHAR
                 Output: 39475 rows (6.16MB, 81 batches), Cpu time: 24.10ms, Blocked wall time: 3.77s, Peak memory: 4.00MB, Memory allocations: 437
                 HashBuild: Input: 81659 rows (39.93MB, 360 batches), Output: 0 rows (0B, 0 batches), Cpu time: 17.41ms, Blocked wall time: 420.89ms, Peak memory: 3.00MB, Memory allocations: 108, Threads: 4
                 HashProbe: Input: 37576 rows (9.12MB, 81 batches), Output: 39475 rows (6.16MB, 81 batches), Cpu time: 6.69ms, Blocked wall time: 3.34s, Peak memory: 1.00MB, Memory allocations: 329, Threads: 4
                -- TableScan[table: orders, range filters: [(o_orderstatus, Filter(BytesValues, deterministic, null not allowed))]] -> o_orderkey:BIGINT, o_orderstatus:VARCHAR
                   Input: 37576 rows (8.87MB, 0 batches), Raw Input: 9800000 rows (199.37MB), Output: 37576 rows (9.12MB, 81 batches), Cpu time: 260.56ms, Blocked wall time: 0ns, Peak memory: 6.00MB, Memory allocations: 6976, Threads: 4, Splits: 10
                -- HashJoin[INNER l_suppkey_1=s_suppkey] -> l_orderkey_1:BIGINT, s_nationkey:BIGINT, l_suppkey_1:BIGINT, s_name:VARCHAR
                   Output: 81659 rows (39.93MB, 360 batches), Cpu time: 13.48ms, Blocked wall time: 33.37ms, Peak memory: 2.00MB, Memory allocations: 1112
                   HashBuild: Input: 4010 rows (1.15MB, 10 batches), Output: 0 rows (0B, 0 batches), Cpu time: 708.22us, Blocked wall time: 2.02ms, Peak memory: 1.00MB, Memory allocations: 9, Threads: 4
                   HashProbe: Input: 81659 rows (19.96MB, 360 batches), Output: 81659 rows (39.93MB, 360 batches), Cpu time: 12.78ms, Blocked wall time: 31.35ms, Peak memory: 1.00MB, Memory allocations: 1103, Threads: 4
                  -- Project[expressions: (l_orderkey_1:BIGINT, ROW["l_orderkey"]), (l_suppkey_1:BIGINT, ROW["l_suppkey"])] -> l_orderkey_1:BIGINT, l_suppkey_1:BIGINT
                     Output: 81659 rows (19.96MB, 360 batches), Cpu time: 818.69us, Blocked wall time: 0ns, Peak memory: 0B, Memory allocations: 0, Threads: 4
                    -- TableScan[table: lineitem, remaining filter: (gt(ROW["l_receiptdate"],ROW["l_commitdate"]))] -> l_suppkey:BIGINT, l_commitdate:DATE, l_orderkey:BIGINT, l_receiptdate:DATE
                       Input: 81659 rows (35.34MB, 0 batches), Raw Input: 3229839 rows (240.41MB), Output: 81659 rows (20.73MB, 360 batches), Cpu time: 2.16s, Blocked wall time: 0ns, Peak memory: 52.00MB, Memory allocations: 5120, Threads: 4, Splits: 10
                  -- HashJoin[INNER s_nationkey=n_nationkey] -> s_suppkey:BIGINT, s_name:VARCHAR, s_nationkey:BIGINT
                     Output: 4010 rows (1.15MB, 10 batches), Cpu time: 718.13us, Blocked wall time: 5.29ms, Peak memory: 1.00MB, Memory allocations: 2
                     HashBuild: Input: 1 rows (124B, 1 batches), Output: 0 rows (0B, 0 batches), Cpu time: 32.53us, Blocked wall time: 387.00us, Peak memory: 1.00MB, Memory allocations: 2, Threads: 4
                     HashProbe: Input: 4010 rows (1.15MB, 10 batches), Output: 4010 rows (1.15MB, 10 batches), Cpu time: 685.60us, Blocked wall time: 4.90ms, Peak memory: 0B, Memory allocations: 0, Threads: 4
                    -- TableScan[table: supplier] -> s_nationkey:BIGINT, s_name:VARCHAR, s_suppkey:BIGINT
                       Input: 4010 rows (5.42MB, 0 batches), Raw Input: 100000 rows (16.19MB), Output: 4010 rows (1.15MB, 10 batches), Cpu time: 11.03ms, Blocked wall time: 0ns, Peak memory: 7.00MB, Memory allocations: 140, Threads: 4, Splits: 10
                    -- TableScan[table: nation, range filters: [(n_name, Filter(BytesValues, deterministic, null not allowed))]] -> n_nationkey:BIGINT, n_name:VARCHAR
                       Input: 1 rows (1.44KB, 0 batches), Raw Input: 25 rows (41.01KB), Output: 1 rows (124B, 1 batches), Cpu time: 1.26ms, Blocked wall time: 0ns, Peak memory: 1.00MB, Memory allocations: 27, Threads: 4, Splits: 10
            -- Project[expressions: (l_orderkey_3:BIGINT, ROW["l_orderkey"]), (l_suppkey_3:BIGINT, ROW["l_suppkey"])] -> l_orderkey_3:BIGINT, l_suppkey_3:BIGINT
               Output: 2041267 rows (38.32MB, 362 batches), Cpu time: 151.20ms, Blocked wall time: 0ns, Peak memory: 0B, Memory allocations: 0, Threads: 4
              -- TableScan[table: lineitem, remaining filter: (gt(ROW["l_receiptdate"],ROW["l_commitdate"]))] -> l_suppkey:BIGINT, l_commitdate:DATE, l_orderkey:BIGINT, l_receiptdate:DATE
                 Input: 2041267 rows (158.66MB, 0 batches), Raw Input: 3229839 rows (240.41MB), Output: 2041267 rows (57.46MB, 362 batches), Cpu time: 1.23s, Blocked wall time: 0ns, Peak memory: 64.00MB, Memory allocations: 5122, Threads: 4, Splits: 10

----------------------

DuckDB results (in Python REPL):
>>> duckdb.sql(q21_sf10).show()
┌────────────────────┬─────────┐
│       s_name       │ numwait │
│      varchar       │  int64  │
├────────────────────┼─────────┤
│ Supplier#000062538 │      24 │
│ Supplier#000032858 │      22 │
│ Supplier#000063723 │      21 │
│ Supplier#000089484 │      21 │
│ Supplier#000007061 │      20 │
│ Supplier#000034162 │      20 │
│ Supplier#000086690 │      20 │
│ Supplier#000097808 │      20 │
│ Supplier#000004163 │      19 │
│ Supplier#000016074 │      19 │
│         ·          │       · │
│         ·          │       · │
│         ·          │       · │
│ Supplier#000099320 │      17 │
│ Supplier#000099325 │      17 │
│ Supplier#000000114 │      16 │
│ Supplier#000000821 │      16 │
│ Supplier#000004199 │      16 │
│ Supplier#000006757 │      16 │
│ Supplier#000006795 │      16 │
│ Supplier#000006824 │      16 │
│ Supplier#000007491 │      16 │
│ Supplier#000008301 │      16 │
├────────────────────┴─────────┤
│     100 rows (20 shown)      │
└──────────────────────────────┘
Yuhta commented 1 year ago

@oerling

pedroerp commented 1 year ago

Is this data being generated using Velox's TPCHConnector? If so, we use a different buffer size for string generation in dbgen, so the data generated won't be exactly equal to the data generated using DuckDB (but not sure if the issue is dbgen or actual query execution here).

lawben commented 1 year ago

@pedroerp Yes, the data is being generated with the TPCHConnector (see #4091 for current version). But I'm using the same data in DuckDB, not their data. However, when using the same generator for SF1, we get the same results as DuckDB. Is there a difference between SF1 and 10 for the buffers?

pedroerp commented 1 year ago

Is there a difference between SF1 and 10 for the buffers?

Not that I know of. The only difference I'm aware of is that the buffers dbgen uses to generate synthetic strings are smaller in Velox (to make them faster to initialize), so strings generated between Velox and DuckDB will be different (regardless of the scale factor).

The issue you're reporting seems unrelated; looks like it might be an actual bug.