search

dimitri / pgloader

Migrate to PostgreSQL in a single command!
http://pgloader.io
Other
5.45k stars 548 forks source link

Hangs while migrating from SQLite3 #1622

Open fluca1978 opened 2 weeks ago

fluca1978 commented 2 weeks ago

pgloader version is 3.6.9 running on Ubuntu 24.04:

% pgloader --version
pgloader version "3.6.9"
compiled with SBCL 2.2.9.debian

 % lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 24.04 LTS
Release:        24.04
Codename:       noble

I use it to migrate from an SQLite3 database of 1.6GB in size to a PostgreSQL server. It starts running but it hangs and does not progress. PostgreSQL version is 16.4 running on Rocky Linux 9; SQLite 3 version is 3.45.1.

My pgloader configuration file is:

% cat pgloader.migrate2PostgreSQL.load
load database
     from sqlite://db/db.sqlite3
     into postgres://franzy@rachel/franzydb

 with include drop, create tables, create no indexes, reset sequences
    , workers = 2, concurrency = 1
    , on error stop
    , batch rows = 1000

set work_mem to '64MB', maintenance_work_mem to '512 MB';

I invoke it as follows (output shown):

 % pgloader -v pgloader.migrate2PostgreSQL.load
2024-11-07T11:10:26.002000+01:00 NOTICE Starting pgloader, log system is ready.
2024-11-07T11:10:26.007000+01:00 LOG pgloader version "3.6.9"
2024-11-07T11:10:26.009000+01:00 LOG Parsing commands from file #P"/home/luca/git/fluca1978/franzy/pgloader.migrate2PostgreSQL.load"
2024-11-07T11:10:26.111002+01:00 LOG Migrating from #<SQLITE-CONNECTION sqlite:///home/luca/git/fluca1978/franzy/db/db.sqlite3 {10068A3ED3}>
2024-11-07T11:10:26.112002+01:00 LOG Migrating into #<PGSQL-CONNECTION pgsql://franzy@rachel:5432/franzydb {10068A4063}>
2024-11-07T11:10:26.130002+01:00 NOTICE SQLite column django_migrations.id uses a sequence
2024-11-07T11:10:26.130002+01:00 NOTICE SQLite column django_content_type.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_group_permissions.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_user_groups.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_user_user_permissions.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_permission.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_group.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column franzy_userinfo.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column eventi.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column django_admin_log.id uses a sequence
2024-11-07T11:10:26.132002+01:00 NOTICE SQLite column tutor_riscontroattivita.id uses a sequence
2024-11-07T11:10:26.132002+01:00 NOTICE SQLite column auth_user.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column esse3_db_sync.pk uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column tutor_categoriaattivita.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column tutor_attivita.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column studente_foto.id uses a sequence
2024-11-07T11:10:26.152002+01:00 NOTICE Prepare PostgreSQL database.
2024-11-07T11:10:27.087018+01:00 NOTICE COPY docenti with 0 rows estimated [1/2]
2024-11-07T11:10:27.125019+01:00 NOTICE COPY docente_corso_di_laurea with 0 rows estimated [1/2]
2024-11-07T11:10:27.129019+01:00 NOTICE COPY corsi_di_studio with 0 rows estimated [1/2]
2024-11-07T11:10:27.133019+01:00 NOTICE COPY percorsi with 0 rows estimated [1/2]
2024-11-07T11:10:27.137019+01:00 NOTICE COPY ordinamenti with 0 rows estimated [1/2]
2024-11-07T11:10:27.140019+01:00 NOTICE COPY studenti with 0 rows estimated [1/2]
2024-11-07T11:10:29.128052+01:00 NOTICE COPY maturita with 0 rows estimated [1/2]
2024-11-07T11:10:29.403057+01:00 ERROR Error while formatting a row from "maturita":
2024-11-07T11:10:29.403057+01:00 ERROR The value
  6.25d0
is not of type
  (OR STRING NULL FIXNUM)
when binding PGLOADER.TRANSFORMS::INTEGER-STRING
2024-11-07T11:10:29.404057+01:00 ERROR The value
  NIL
is not of type
  NUMBER
2024-11-07T11:10:29.405057+01:00 WARNING PostgreSQL warning: there is no transaction in progress

At this point, the program is stuck. On the PostgreSQL side, I see there is no activity (apparently):

franzydb=# select datname, query, wait_event, wait_event_type from pg_stat_activity where datname = 'franzydb';
-[ RECORD 1 ]---+-------------------------------------------------------------------------------------------------------
datname         | franzydb
query           | select datname, query, wait_event, wait_event_type from pg_stat_activity where datname = 'franzydb';
wait_event      |
wait_event_type |
-[ RECORD 2 ]---+-------------------------------------------------------------------------------------------------------
datname         | franzydb
query           |                                                                                                       +
                | copy scuola (id,nome,tipo_codice,tipo,comune,provincia) FROM STDIN
wait_event      | ClientRead
wait_event_type | Client

franzydb=# select command, bytes_processed, bytes_total, tuples_processed from pg_stat_progress_copy ;
-[ RECORD 1 ]----+----------
command          | COPY FROM
bytes_processed  | 0
bytes_total      | 0
tuples_processed | 0

On the SQLite3 side, the table it is trying to copy (scuola) is:

sqlite> SELECT SUM("pgsize") FROM "dbstat" WHERE name='scuola';
3235840

If I run pgloader with -d, the point where it hangs is:

024-11-07T11:13:07.621044+01:00 INFO COPY ON ERROR STOP
2024-11-07T11:13:07.657044+01:00 DEBUG CONNECTED TO #<PGLOADER.PGSQL:PGSQL-CONNECTION pgsql://franzy@rachel:5432/franzydb {1005B5A703}>
2024-11-07T11:13:07.657044+01:00 DEBUG SET client_encoding TO 'utf8'
2024-11-07T11:13:07.657044+01:00 DEBUG SET work_mem TO '64MB'
2024-11-07T11:13:07.658044+01:00 DEBUG SET maintenance_work_mem TO '512 MB'
2024-11-07T11:13:07.658044+01:00 DEBUG SET application_name TO 'pgloader'
2024-11-07T11:13:07.659044+01:00 INFO pgsql:copy-rows-from-queue[0]: scuola (id nome tipo_codice tipo comune
                                       provincia)

and no other messages can be found in the logs.

Considering that there is an error launched on tbale maturita, while the COPY is active on another table, I tried to search for such a value causing the error, without any success:

% sqlite3 -line db/db.sqlite3  'select * from maturita;' | grep "25d0" | wc -l
0

On the PostgreSQL side, around the point where pgloader hangs, I find:

 CET [32805]: [17] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.048 ms  bind <unnamed>: select version()
 CET [32805]: [18] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.033 ms  execute <unnamed>: select version()
 CET [32805]: [19] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: BEGIN
 CET [32805]: [20] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.002 ms  bind <unnamed>: BEGIN
 CET [32805]: [21] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  execute <unnamed>: BEGIN
 CET [32805]: [22] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 47.217 ms  statement: 
        copy maturita (id,studente_id,anno,voto_massimo,voto,lode,titolo,scuola_id) FROM STDIN
 CET [32805]: [23] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.010 ms  parse <unnamed>: COMMIT
 CET [32805]: [24] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.004 ms  bind <unnamed>: COMMIT
 CET [32805]: [25] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.147 ms  execute <unnamed>: COMMIT
 CET [32805]: [26] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: ROLLBACK
 CET [32805]: [27] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: ROLLBACK
 CET [32805]: [28] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 WARNING:  there is no transaction in progress
 CET [32805]: [29] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.082 ms  execute <unnamed>: ROLLBACK
 CET [32805]: [30] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  disconnection: session time: 0:00:00.063 user=franzy database=franzydb host=192.168.222.1 port=57646
 CET [32806]: [1] user=[unknown],db=[unknown],app=[unknown],client=192.168.222.1 LOG:  connection received: host=192.168.222.1 port=57660
 CET [32806]: [2] user=franzy,db=franzydb,app=[unknown],client=192.168.222.1 LOG:  connection authenticated: identity="franzy" method=scram-sha-256 (/postgres/16/data/pg_hba.conf:128)
 CET [32806]: [3] user=franzy,db=franzydb,app=[unknown],client=192.168.222.1 LOG:  connection authorized: user=franzy database=franzydb application_name=postmodern-default
 CET [32806]: [4] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.063 ms  parse <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [5] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.014 ms  bind <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [6] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.011 ms  execute <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [7] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.009 ms  parse <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [8] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [9] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  execute <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [10] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.006 ms  parse <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [11] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.002 ms  bind <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [12] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  execute <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [13] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [14] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [15] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.004 ms  execute <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [16] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.141 ms  parse <unnamed>: select version()
 CET [32806]: [17] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.049 ms  bind <unnamed>: select version()
 CET [32806]: [18] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.007 ms  execute <unnamed>: select version()
 CET [32806]: [19] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: BEGIN
 CET [32806]: [20] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: BEGIN
 CET [32806]: [21] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  execute <unnamed>: BEGIN

I cannot spot the problem at all.

fluca1978 commented 2 weeks ago

Update on the problem: I tested the same loading excluding the scuola table and the application loaded almost everything. Note that another table has a very similar problem, but: 1) the pgloader this time continues; 2) the valure that raised the error is very similar in form to the previous one, so I suspect it is not the real value rather a mangled one.

2024-11-07T13:25:18.700492Z NOTICE COPY lauree with 0 rows estimated [1/2]
2024-11-07T13:25:21.091531Z ERROR Error while formatting a row from "lauree":
2024-11-07T13:25:21.105531Z ERROR The value
  90.22d0
is not of type
  (OR STRING NULL FIXNUM)
when binding PGLOADER.TRANSFORMS::INTEGER-STRING
2024-11-07T13:25:21.148532Z ERROR The value
  NIL
is not of type
  NUMBER
2024-11-07T13:25:21.158532Z WARNING PostgreSQL warning: there is no transaction in progress
2024-11-07T13:25:21.801542Z NOTICE COPY e_db_sync with 0 rows estimated [1/2]
2024-11-07T13:25:21.845543Z NOTICE COPY tutor_categoriaattivita with 0 rows estimated [1/2]
2024-11-07T13:25:21.845543Z NOTICE COPY tutor_attivita with 0 rows estimated [1/2]
2024-11-07T13:25:21.941544Z NOTICE COPY studente_foto with 0 rows estimated [1/2]
2024-11-07T13:25:27.739637Z NOTICE copy studente_foto: 495781 rows done,  38.5 MB,   6.6 MBps
2024-11-07T13:25:27.762638Z NOTICE Completing PostgreSQL database.

So, how can I find out what are the rows causing the problem, so that I can fix them? Second, why is not pgloader stopping once I've configured on error stop in the configuration file? Am I doing something wrong?