Bug: Hang during COPY with large set

[mahlonsmith]

Ladybug version

v0.18.0

What operating system are you using?

Linux

What happened?

I've got an importer I use for a dataset generator (here) -- under v0.16.0, the import takes about 10 seconds.

% ./imdb_import
Skipping name.basics, csv already exists.
Skipping title.basics, csv already exists.
Skipping title.principals, csv already exists.
Created database schema in 24ms.
COPY Actor FROM "./name.basics.csv" (header=true)
COPY Movie FROM "./title.basics.csv" (header=true)
COPY ActedIn FROM "./title.principals.csv" (header=true, ignore_errors=true)
COPY ActedIn FROM "./known.principals.csv" (header=true, ignore_errors=true)
Imported data in 10.802s.
Done!

Under v0.18.0, it hangs with 100% CPU during the "title.principals.csv" import (the largest one) -- I've let it churn for about 2 hours before cancelling. Looks like the behavior started in v0.17.0.

Interestingly, I can EXPORT the v0.16.0 data, and IMPORT it into v0.18.0 without any problem. Not sure how to go about diagnosing this further, but figure it's worth reporting.

Are there known steps to reproduce?

No response

[mahlonsmith]

Hmm, I just ran all the COPY commands from the lbug shell directly and it was fine, implying it might be something amiss in my bindings between versions. Very odd.

In any event, this seems more likely to be a "me problem", apologies for the noise.

[mahlonsmith]

Well crud.

I must have been moving too quickly and my CLI success was under 0.16.0, because unfortunately, it does indeed hang for me in the 0.18.0 CLI.

% lbug imdb.db
Opening the database at path: imdb.db in read-write mode.
Enter ":help" for usage hints.
lbug> :schema
CREATE NODE TABLE `Movie` (`movieId` INT64,`title` STRING,`year` UINT16,`durationMins` INT32, PRIMARY KEY(`movieId`));
CREATE NODE TABLE `Actor` (`actorId` INT64,`name` STRING,`birthYear` UINT16,`deathYear` UINT16, PRIMARY KEY(`actorId`));
CREATE REL TABLE `ActedIn` (FROM `Actor` TO `Movie`, MANY_MANY);
lbug> COPY Actor FROM "./name.basics.csv" (header=true);
┌────────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                             │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                             │ INT64                      │ STRING[]              │
├────────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 13594338 tuples have been copied to the Actor ta...│  0                         │  []                   │
└────────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 2.42ms (compiling), 2904.79ms (executing)
lbug> COPY Movie FROM "./title.basics.csv" (header=true);
┌────────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                             │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                             │ INT64                      │ STRING[]              │
├────────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 750860 tuples have been copied to the Movie table. │ 0                          │ []                    │
└────────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 1.52ms (compiling), 658.05ms (executing)
lbug> COPY ActedIn FROM "./title.principals.csv" (header=true, ignore_errors=true);
*** hangs here ***

I should note at this point I can't ctrl-c to cancel. There's no pipeline/progress message that appears at all. I have to kill the process.

On a hunch I took the first 1000 lines of the CSV and just tried to import that:

lbug> COPY ActedIn FROM "./smaller_test.csv" (header=true, ignore_errors=true);
┌─────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ result                                                                                                  │
│ STRING                                                                                                  │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ 39 tuples have been copied to the ActedIn table.                                                        │
│ 960 warnings encountered during copy. Use 'CALL show_warnings() RETURN *' to view the actual warnings...│
└─────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(2 tuples)
(1 column)
Time: 0.82ms (compiling), 10634.02ms (executing)

It worked, but it was extremely slow. (The warnings are fine, this dataset has a bunch of TV actors and the parser is focusing on movies, specifically.) 10 seconds for those 1000 rows (the full file has 41631105 rows), and comparing that to the successful Actor name import of 13594338 rows in about 3 seconds. The only obvious difference I see is that it is copying into a REL.

Some more miscellanea:

• I tried disabling SPILL_TO_DISK with no effect.
• I repeated all of this on FreeBSD using the port (builds from source) and everything worked as expected. (I initially saw this problem on Arch Linux, using the binary AUR package and generated artifacts.)
• Suspecting the build artifacts, I built Ladybug from source on Arch and tried again. Same result.

You can see the AUR package recipe here -- nothing particularly magical. The FreeBSD port makes an attempt to unbundle what third party packages it can - leading me to believe the problem might have been caused by a difference in the bundled third_party, somewhere after version 0.16.0? Kind of a stab. I rebuilt it on FreeBSD manually without unbundling anything to verify -- and nope, still works fine.

So other than "it works on FreeBSD but not on Linux", I don't have much more useful information to share.

Let me know if I can do any further elimination or diagnostics. I can make the dataset available if that's helpful for reproduction.

[adsharma]

Can't repro on HEAD. Please retest after 0.18.1 is released.

I couldn't test 0.18.0 because of #667

lbug> COPY Actor FROM "./name.basics.trimmed.csv" (header=true, DELIM='\t', ignore_errors=True);
┌──────────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                               │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                               │ INT64                      │ STRING[]              │
├──────────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 15468442 tuples have been copied to the Actor table. │ 0                          │ []                    │
└──────────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 2.61ms (compiling), 9392.21ms (executing)
lbug> COPY Movie FROM "./title.basics.trimmed.csv" (header=true, DELIM='\t', ignore_errors=True);
┌──────────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                               │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                               │ INT64                      │ STRING[]              │
├──────────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 12623653 tuples have been copied to the Movie table. │ 0                          │ []                    │
└──────────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 2.71ms (compiling), 8645.39ms (executing)
lbug> COPY ActedIn FROM "./title.principals.trimmed.csv" (header=true, DELIM='\t', ignore_errors=true);
┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ result                                                                                                              │
│ STRING                                                                                                              │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ 100336393 tuples have been copied to the ActedIn table.                                                             │
│ 6845 warnings encountered during copy. Use 'CALL show_warnings() RETURN *' to view the actual warnings. Query ID: 5 │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(2 tuples)
(1 column)
Time: 1.71ms (compiling), 41782.59ms (executing)

[adsharma]

The dataset I used for the test should appear here in a few mins:

https://huggingface.co/datasets/ladybugdb/imdb-tsv/tree/main

[mahlonsmith]

Nice, okay. My tsv->csv converted (also stripped all the leading zeros) is here:

https://martini.nu/misc/dataset_csv.tgz

I'll try both with HEAD.

[adsharma]

Works for me with 0.18.0 and Linux.
Potential vectors to investigate: Running out of memory, crashes manifesting as hangs due to 8TB virtual

[mahlonsmith]

My mystery deepens.

It appears there's some difference between the database file created by my importer (using nim bindings), and a database created by the ladybug cli directly, which was likely what was confusing my initial attempts, along with today's.

If I create a schema from my importer script, I'm unable to import the REL data, even using the CLI. This is the case even if I ONLY create the schema and leave the database empty -- I can't COPY even though the schema appears to be correctly present. If I perform the same steps from C manually, everything is fine. If I create the schema externally, then use the binding to import the data, it's fine.

(schema creation done using the CLI first)

❯ ./imdb_import
Skipping name.basics, csv already exists.
Skipping title.basics, csv already exists.
Skipping title.principals, csv already exists.
COPY Actor FROM "./name.basics.csv" (header=true)
COPY Movie FROM "./title.basics.csv" (header=true)
COPY ActedIn FROM "./title.principals.csv" (header=true, ignore_errors=true)
COPY ActedIn FROM "./known.principals.csv" (header=true, ignore_errors=true)
Imported data in 24.743s.
Done!

This.... is a head scratcher. Back to thinking it's something in my binding since it works from C -- but the binding is using the same C, and it seems fine previous to 0.17.0.

More research needed here. Thanks for being a sounding board.

[mahlonsmith]

Yeah, hm.

# Created entirely from the CLI
% lbug imdb-cli.db
lbug> :schema
CREATE NODE TABLE `Movie` (`movieId` INT64,`title` STRING,`year` UINT16,`durationMins` INT32, PRIMARY KEY(`movieId`));
CREATE NODE TABLE `Actor` (`actorId` INT64,`name` STRING,`birthYear` UINT16,`deathYear` UINT16, PRIMARY KEY(`actorId`));
CREATE REL TABLE `ActedIn` (FROM `Actor` TO `Movie`, MANY_MANY);
lbug> :quit

# Schema created from bindings
% lbug imdb-bindings.db
lbug> :schema
CREATE NODE TABLE `Movie` (`movieId` INT64,`title` STRING,`year` UINT16,`durationMins` INT32, PRIMARY KEY(`movieId`));
CREATE NODE TABLE `Actor` (`actorId` INT64,`name` STRING,`birthYear` UINT16,`deathYear` UINT16, PRIMARY KEY(`actorId`));
CREATE REL TABLE `ActedIn` (FROM `Actor` TO `Movie`, MANY_MANY);
lbug> :quit

% lbug imdb-cli.db
Opening the database at path: imdb-cli.db in read-write mode.
Enter ":help" for usage hints.
lbug> COPY Actor FROM "./name.basics.csv" (header=true);
┌───────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                            │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                            │ INT64                      │ STRING[]              │
├───────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 13606458 tuples have been copied to the Actor t...│  0                         │  []                   │
└───────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 2.34ms (compiling), 2988.90ms (executing)
lbug> COPY Movie FROM "./title.basics.csv" (header=true);
┌───────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                            │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                            │ INT64                      │ STRING[]              │
├───────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 751370 tuples have been copied to the Movie tab...│  0                         │  []                   │
└───────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 1.49ms (compiling), 710.93ms (executing)
lbug> COPY ActedIn FROM "./title.principals.csv" (header=true, ignore_errors=true);
┌────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ result                                                                                                 │
│ STRING                                                                                                 │
├────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ 4108595 tuples have been copied to the ActedIn table.                                                  │
│ 37563427 warnings encountered during copy. Use 'CALL show_warnings() RETURN *' to view the actual wa...│
└────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(2 tuples)
(1 column)
Time: 0.86ms (compiling), 7058.93ms (executing)

% lbug imdb-bindings.db
Opening the database at path: imdb-bindings.db in read-write mode.
Enter ":help" for usage hints.
lbug> COPY Actor FROM "./name.basics.csv" (header=true);
┌───────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                            │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                            │ INT64                      │ STRING[]              │
├───────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 13606458 tuples have been copied to the Actor t...│  0                         │  []                   │
└───────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 2.13ms (compiling), 2658.99ms (executing)
lbug> COPY Movie FROM "./title.basics.csv" (header=true);
┌───────────────────────────────────────────────────┬────────────────────────────┬───────────────────────┐
│ result                                            │ skipped_duplicate_pk_count │ skipped_duplicate_pks │
│ STRING                                            │ INT64                      │ STRING[]              │
├───────────────────────────────────────────────────┼────────────────────────────┼───────────────────────┤
│ 751370 tuples have been copied to the Movie tab...│  0                         │  []                   │
└───────────────────────────────────────────────────┴────────────────────────────┴───────────────────────┘
(1 tuple)
(3 columns)
Time: 1.49ms (compiling), 621.11ms (executing)
lbug> COPY ActedIn FROM "./title.principals.csv" (header=true, ignore_errors=true);
*** hang! ***

Back to my original comment of this seeming to be a "me problem", but I'm interested in what's different on disk here where the schema looks proper but something ain't kosher somehow.

[mahlonsmith]

Something I forgot from earlier today that feels like a wrench in the machine: That truncated 1000 line CSV that still worked from a "binding weird" database, but taking 10 seconds to import.

In case putting up a "binding made schema" empty database somewhere help if you have tooling to see if there's an internal structure or something that is incomplete (or can replicate this behavior with it) -- I put one up here that seems to be tainted.

[adsharma]

Also useful to compare:

lbug> CALL disk_size_info() return *;
lbug> CALL show_indexes() return *;

Is it possible that one is running with Hash index and the other with ART index?

[mahlonsmith]

Oh, very interesting.

❯ lbug imdb-cli.db
Opening the database at path: imdb-cli.db in read-write mode.
Enter ":help" for usage hints.
lbug> CALL disk_size_info() return *;
┌────────────┬──────────────────────┬───────────┬────────────┐
│ category   │ name                 │ num_pages │ size_bytes │
│ STRING     │ STRING               │ UINT64    │ UINT64     │
├────────────┼──────────────────────┼───────────┼────────────┤
│ header     │ database_header      │ 1         │ 4096       │
│ catalog    │ catalog              │ 1         │ 4096       │
│ metadata   │ metadata             │ 2         │ 8192       │
│ node_table │ Movie                │ 0         │ 0          │
│ node_table │ Actor                │ 0         │ 0          │
│ rel_table  │ ActedIn:Actor->Movie │ 0         │ 0          │
│ free_space │ free_pages           │ 0         │ 0          │
│ total      │ file_total           │ 4         │ 16384      │
└────────────┴──────────────────────┴───────────┴────────────┘
(8 tuples)
(4 columns)
Time: 2.68ms (compiling), 0.46ms (executing)
lbug> CALL show_indexes() return *;
┌────────────┬────────────┬────────────┬────────────────┬──────────────────┬──────────────────┐
│ table_name │ index_name │ index_type │ property_names │ extension_loaded │ index_definition │
│ STRING     │ STRING     │ STRING     │ STRING[]       │ BOOL             │ STRING           │
├────────────┼────────────┼────────────┼────────────────┼──────────────────┼──────────────────┤
│ Movie      │ _PK        │ HASH       │ [movieId]      │ True             │                  │
│ Actor      │ _PK        │ HASH       │ [actorId]      │ True             │                  │
└────────────┴────────────┴────────────┴────────────────┴──────────────────┴──────────────────┘
(2 tuples)
(6 columns)
Time: 0.22ms (compiling), 0.26ms (executing)

❯ lbug imdb-bindings.db
Opening the database at path: imdb-bindings.db in read-write mode.
Enter ":help" for usage hints.
lbug> CALL disk_size_info() return *;
┌────────────┬──────────────────────┬───────────┬────────────┐
│ category   │ name                 │ num_pages │ size_bytes │
│ STRING     │ STRING               │ UINT64    │ UINT64     │
├────────────┼──────────────────────┼───────────┼────────────┤
│ header     │ database_header      │ 1         │ 4096       │
│ catalog    │ catalog              │ 1         │ 4096       │
│ metadata   │ metadata             │ 2         │ 8192       │
│ node_table │ Movie                │ 0         │ 0          │
│ node_table │ Actor                │ 0         │ 0          │
│ rel_table  │ ActedIn:Actor->Movie │ 0         │ 0          │
│ free_space │ free_pages           │ 0         │ 0          │
│ total      │ file_total           │ 4         │ 16384      │
└────────────┴──────────────────────┴───────────┴────────────┘
(8 tuples)
(4 columns)
Time: 2.35ms (compiling), 0.42ms (executing)
lbug> CALL show_indexes() return *;
┌────────────┬────────────┬────────────┬────────────────┬──────────────────┬──────────────────┐
│ table_name │ index_name │ index_type │ property_names │ extension_loaded │ index_definition │
│ STRING     │ STRING     │ STRING     │ STRING[]       │ BOOL             │ STRING           │
├────────────┼────────────┼────────────┼────────────────┼──────────────────┼──────────────────┤
└────────────┴────────────┴────────────┴────────────────┴──────────────────┴──────────────────┘
(0 tuples)
(6 columns)
Time: 0.21ms (compiling), 0.26ms (executing)

No indexing whatsoever?

[adsharma]

0.18.0 reports hash index in show_indexes(). Earlier versions didn't (they assumed that it was always going to be there, no need for reporting).

That suggests that your other version is not really 0.18.x.