Myloader hung at Reading metadata: metadata

[tylerhowdcgm]

Describe the bug
Im dumping from RDS Mysql 8 and importing into Aurora. Total dump size is 105G. The dump took a bit over an hour, but the load into Aurora has be hung at Reading metadata: metadata for over 2 hours. Is this expected behavior? Am I doing something wrong?

To Reproduce
Command executed:
mydumper -t 14 -u USER --password='PASSWORD' -h rds-database.us-east-1.rds.amazonaws.com -P 3306 -o /home/ubuntu/backup --lock-all-tables -v 3 -R -Y

myloader --threads=14 -u USER --password='PASSWORD' -h 'aurora.us-east-1.rds.amazonaws.com' -P 3306 -v 3 -d /home/ubuntu/backup

What mydumper and myloader version has been used?
mydumper v0.16.1-3
myloader v0.16.1-3

Expected behavior
The import to start

Environment (please complete the following information):
Ubuntu 22.04

Other info:
I just installed the latest deb and im testing again

[tylerhowdcgm]

Ok I think I know whats going on. Myloader is skipping every table because the schema doesnt exist. I dumped the entire database, but not the schemas? Is it just skipping everything? How can I just load schemas and tables? I have a ton of schemas and specifying each one to dump and then load would be crazy.

** (myloader:2748): DEBUG: 21:42:31.390: [CJT] sandbox_****_.auto_coding: NOT_FOUND, voting for finish
** (myloader:2748): DEBUG: 21:42:31.390: [CJT] No job available
** (myloader:2748): DEBUG: 21:42:31.390: [CJT] Thread will be waiting

[davidducos]

Hi @tylerhowdcgm can you test with the latest prerelease?

[tylerhowdcgm]

Thanks for the reply. I installed the v0.16.2-2 deb. Is there a newer release?

[davidducos]

Hi @tylerhowdcgm yes, v0.16.2-2 is the latest prerelease. do you have the same issue on that version? if yes, then can you share the metadata file?

[tylerhowdcgm]

It is happening with that version. I took a look at the metadata file and it has some sensitive information in it about our customers. Its also quite long. Is there an easy way to scrub it or provide me with what you are looking for? I can comb through the metadata a look for what you need.

[davidducos]

Yes! I know, but no worries, How many tables do you have there? can you share just 1 table example editing the sensitive information? there are global sections on that file that might not contain sensitive information, I will need those too.

[tylerhowdcgm]

Global section

# Started dump at: 2024-05-08 20:10:54
[config]
quote_character = BACKTICK

[myloader_session_variables]
SQL_MODE='NO_AUTO_VALUE_ON_ZERO,NO_ENGINE_SUBSTITUTION' /*!40101

[master]
# Channel_Name = '' # It can be use to setup replication FOR CHANNEL
File = mysql-bin-changelog.766700
Position = 157
Executed_Gtid_Set = 

Table example

[`****_*****_migrate_moving_all`.`amendment_info`]
real_table_name=amendment_info
rows = 1356

Oh, we have 42k tables

[tylerhowdcgm]

I only see tables in the metadata file. Nothing about schemas.

[tylerhowdcgm]

I created all the schemas with a script and its still skipping all the tables. Not sure what I did wrong.

[davidducos]

Hi @tylerhowdcgm, does the schema names has special characters?

[tylerhowdcgm]

We have underscores in just about every schema name. No other special characters.

[davidducos]

Bug found!
the issue is when <SCHEMA_NAME>-schema-create.sql file is not found.

[tylerhowdcgm]

I built the master branch and installed. It looks to me like it has the same issue.

[davidducos]

Hi @tylerhowdcgm,
there is available a new prereleases, v0.16.2-3 which includes the fix, as the error that you mention should be fixed. I know that you compiled from master but I want you to test the binaries to avoid an issue when you build your packages.

[tylerhowdcgm]

I assume we will have to do a new dump because the metadata file has changed with this fix?

[davidducos]

Hi @tylerhowdcgm,
No, there is no need to dump a new dump, as myloader will try to import the table, if the schema is not found, it will be enqueuing the job again, and if it reaches the same point it will consider that the schema is there and import the table. It might fail for other reasons, but that is up to you to fix.

[davidducos]

Hi @tylerhowdcgm Can we close this issue?

[alexoj]

Hi, I'm not the original poster but I have the same issue:

** Message: 01:05:55.801: Using 4 loader threads
** Message: 01:05:55.805: Connection via default library settings using password:
        User: root
** Message: 01:05:55.806: Initializing initialize_worker_schema
** (myloader:49497): DEBUG: 01:05:55.806: [S05] S-Thread 5: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [S08] S-Thread 8: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [S06] S-Thread 6: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [S07] S-Thread 7: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [I10] I-Thread 10: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [I12] I-Thread 12: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [CJT] Thread control_job_thread paused
** (myloader:49497): DEBUG: 01:05:55.807: [T01] Thread 1: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [I09] I-Thread 9: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [I11] I-Thread 11: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [T01] refresh_db_queue <- THREAD
** (myloader:49497): DEBUG: 01:05:55.807: [T02] Thread 2: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [T02] refresh_db_queue <- THREAD
** (myloader:49497): DEBUG: 01:05:55.807: [T03] Thread 3: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [T03] refresh_db_queue <- THREAD
** (myloader:49497): DEBUG: 01:05:55.807: [T04] Thread 4: Starting import
** (myloader:49497): DEBUG: 01:05:55.807: [T04] refresh_db_queue <- THREAD
** (myloader:49497): DEBUG: 01:05:55.846: [MDT] Reading metadata: metadata
** (myloader:49497): DEBUG: 01:05:55.849: [MDT] metadata: quote character is `
<-- Stuck here for a long time with the MDT thread taking 100% CPU.

(gdb) bt
#0  compare_dbt_short (a=0x563901808920, b=0x563901887ac0) at /tmp/src/mydumper/src/myloader_common.c:403
#1  0x00007fca380d5940 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2  0x00005638feb55f63 in refresh_table_list_without_table_hash_lock (conf=0x7ffff1653560) at /tmp/src/mydumper/src/myloader_common.c:415
#3  0x00005638feb5237e in append_new_db_table (real_db_name=0x563901d50270, table=0x563901d66f80 "<redacted>", number_rows=0, alter_table_statement=0x0) at /tmp/src/mydumper/src/myloader_process.c:93
#4  0x00005638feb53e9b in process_metadata_global (file=0x5638fec6ce25 "metadata") at /tmp/src/mydumper/src/myloader_process.c:568
#5  0x00005638feb568d4 in process_directory (conf=0x7ffff1653560) at /tmp/src/mydumper/src/myloader_directory.c:61
#6  0x00005638feb4b0f2 in main (argc=10, argv=0x7ffff1653728) at /tmp/src/mydumper/src/myloader.c:516

It seems to spend most of its time in this loop in refresh_table_list_without_table_hash_lock:

  while ( g_hash_table_iter_next ( &iter, (gpointer *) &lkey, (gpointer *) &dbt ) ) {
 //   table_list=g_list_insert_sorted_with_data (table_list,dbt,&compare_dbt,conf->table_hash);
    table_list=g_list_insert_sorted(table_list,dbt,&compare_dbt_short);
  }

My guess is that append_new_db_table is too slow when there's a large number of tables:

# cat metadata | grep real_table_name | wc -l
22705

[davidducos]

Hi @alexoj !! THANKS for you review! yes, that is a important finding, I'm going to modify myloader to avoid this performance degradation. I will also review mydumper to confirm that the metadata.partial are not re sending the tables that were already sent.
Regards