Igor Gaponenko added a comment - 09/Jun/17 6:08 PM - edited Loading catalog allsky_2band_p1bs_psd into PDAC The loading protocol is explained in details at: https://confluence.lsstcorp.org/display/DM/Loading+WISE+catalogs+into+PDAC The rest of this section presents a short summary of actions and tests taken during this loading. Dataset configuration Database name: wise_2band_00 Do this at lsst-dev : % cd /datasets/gapon/development/db_pdac_wise/scripts % ln -s dataset. bash .wise_2band_00 dataset. bash Creating database and initializing CSS All these steps were conducted on the master node of the cluster lsst-qserv-master01 : % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_create_database . bash \ --delete --verbose >& run_create_database.log&   % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/setup_css . bash \ >& setup_css.log % source /datasets/gapon/stack/loadLSST . bash % setup -t qserv-dev qserv_distrib; setup -j -r /datasets/gapon/development/qserv % qserv-admin.py "DUMP EVERYTHING;" | grep wise_2band_00 /DBS/wise_2band_00 READY /DBS/wise_2band_00/ .packed.json { "partitioningId" : "0000000027" , "releaseStatus" : "RELEASED" , "storageClass" : "L2" } /DBS/wise_2band_00/TABLES \N /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd READY /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd/partitioning \N /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd/partitioning/ .packed.json { "dirColName" : "source_id" , "dirDb" : "wise_2band_00" , "dirTable" : "allsky_2band_p1bs_psd" , "latColName" : "decl" , "lonColName" : "ra" , "subChunks" : "1" } /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd/schema ( /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd/sharedScan \N /DBS/wise_2band_00/TABLES/allsky_2band_p1bs_psd/sharedScan/ .packed.json { "lockInMem" : "1" } Configuring MySQL server and Docker container /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_show_processlist . bash --total   % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_set_max_connections . bash   % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_show_processlist . bash --total sst-qserv-master01: 14 / 16384 lsst-qserv-db01: 2 / 16384 lsst-qserv-db02: 2 / 16384 lsst-qserv-db03: 2 / 16384 ... % docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 44d15b27eac2 qserv /qserv :tickets_DM-10283_master "/bin/sh -c /qserv/sc" 2 weeks ago Up 2 weeks qserv   % docker inspect qserv   "Mounts" : [ { "Source" : "/qserv/data" , "Destination" : "/qserv/data" , "Mode" : "" , "RW" : true , "Propagation" : "rprivate" }, { "Source" : "/qserv/log" , "Destination" : "/qserv/run/var/log" , "Mode" : "" , "RW" : true , "Propagation" : "rprivate" }, { "Source" : "/qserv/tmp" , "Destination" : "/qserv/run/tmp" , "Mode" : "" , "RW" : true , "Propagation" : "rprivate" } ], Loading partitioned tables % nohup /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_load_object . bash \ --verbose \ >& run_load_object.log& Testing results: % tail /tmp/wise_2band_00/log/qserv-db *_load_object.log | grep 'Finished' | wc -l 30   % tail /tmp/wise_2band_00/log/qserv-db *_load_object.log | grep 'Finished' [Sat Jun 10 13:59:28 CDT 2017] ** Finished loading ** [Sat Jun 10 13:50:58 CDT 2017] ** Finished loading ** [Sat Jun 10 13:39:20 CDT 2017] ** Finished loading ** [Sat Jun 10 13:33:27 CDT 2017] ** Finished loading ** [Sat Jun 10 13:28:02 CDT 2017] ** Finished loading ** [Sat Jun 10 13:28:10 CDT 2017] ** Finished loading ** [Sat Jun 10 13:24:06 CDT 2017] ** Finished loading ** [Sat Jun 10 13:22:07 CDT 2017] ** Finished loading ** [Sat Jun 10 13:12:26 CDT 2017] ** Finished loading ** [Sat Jun 10 13:12:15 CDT 2017] ** Finished loading ** [Sat Jun 10 13:16:00 CDT 2017] ** Finished loading ** [Sat Jun 10 13:14:34 CDT 2017] ** Finished loading ** [Sat Jun 10 13:18:59 CDT 2017] ** Finished loading ** [Sat Jun 10 13:11:46 CDT 2017] ** Finished loading ** [Sat Jun 10 13:13:28 CDT 2017] ** Finished loading ** [Sat Jun 10 13:25:58 CDT 2017] ** Finished loading ** [Sat Jun 10 13:30:49 CDT 2017] ** Finished loading ** [Sat Jun 10 13:22:43 CDT 2017] ** Finished loading ** [Sat Jun 10 13:21:04 CDT 2017] ** Finished loading ** [Sat Jun 10 13:23:58 CDT 2017] ** Finished loading ** [Sat Jun 10 13:25:21 CDT 2017] ** Finished loading ** [Sat Jun 10 13:38:21 CDT 2017] ** Finished loading ** [Sat Jun 10 13:37:53 CDT 2017] ** Finished loading ** [Sat Jun 10 13:31:47 CDT 2017] ** Finished loading ** [Sat Jun 10 13:25:03 CDT 2017] ** Finished loading ** [Sat Jun 10 13:27:11 CDT 2017] ** Finished loading ** [Sat Jun 10 13:25:20 CDT 2017] ** Finished loading ** [Sat Jun 10 13:34:24 CDT 2017] ** Finished loading ** [Sat Jun 10 13:43:53 CDT 2017] ** Finished loading ** [Sat Jun 10 13:57:27 CDT 2017] ** Finished loading ** Generating the secondary index (FIRST ATTEMPT) Harvesting triplets: % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_dump_triplet . bash \ --verbose \ >& run_dump_triplet.log& Loading triplets into the index: % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose \ --get-remote-triplets \ >& load_secondary_index.log& Performance degradation after loading 60% of TSV files The number of files which have been loaded: % cat load_secondary_index.log | grep 'loading tri' | wc -l 63104 SHOW PROCESSLIST; | 64107 | root | localhost | NULL | Query | 9519 | reading file | LOAD DATA INFILE '/qserv/data/dumps/wise_2band_00/idx_object_200800.tsv' INTO TABLE qservMeta.wise_2 | 36.303 | Actually, the gradual performance degradation was seen much earlier. Later it become more obvious before it literally stalled while loading file idx_object_200800.tsv as per the log file analysis: % cat load_secondary_index.log | grep 'loading tri' | tail -3 loading triplest from file : idx_object_200798.tsv loading triplest from file : idx_object_200799.tsv loading triplest from file : idx_object_200800.tsv The last file is being loaded for the last 2 hours (at least). The file is noticeable larger than the previous ones: % sudo ls -al /qserv/data/dumps/wise_2band_00/ | grep -B 4 -A 4 idx_object_200800.tsv -rw-r--r-- 1 qserv qserv 23608289 Jun 10 20:54 idx_object_200796.tsv -rw-r--r-- 1 qserv qserv 30216240 Jun 10 21:11 idx_object_200797.tsv -rw-r--r-- 1 qserv qserv 44797664 Jun 10 21:28 idx_object_200798.tsv -rw-r--r-- 1 qserv qserv 73420288 Jun 10 21:44 idx_object_200799.tsv -rw-r--r-- 1 qserv qserv 148547683 Jun 10 22:02 idx_object_200800.tsv -rw-r--r-- 1 qserv qserv 156758880 Jun 10 22:19 idx_object_200801.tsv -rw-r--r-- 1 qserv qserv 75832749 Jun 10 22:35 idx_object_200802.tsv -rw-r--r-- 1 qserv qserv 42320964 Jun 10 22:53 idx_object_200803.tsv -rw-r--r-- 1 qserv qserv 30272316 Jun 10 23:10 idx_object_200804.tsv Reconfiguring InnoDB Further analysis of the database service configuration showed that the server runs with the default configuration of the InnoDB storage engine. This configuration seems to be way to suboptimal for the large bulk inserts. This is seen with: SHOW VARIABLES LIKE 'innodb_buffer_pool_%' ; + -------------------------------------+----------------+ | Variable_name | Value | + -------------------------------------+----------------+ | innodb_buffer_pool_dump_at_shutdown | OFF | | innodb_buffer_pool_dump_now | OFF | | innodb_buffer_pool_dump_pct | 100 | | innodb_buffer_pool_filename | ib_buffer_pool | | innodb_buffer_pool_instances | 8 | | innodb_buffer_pool_load_abort | OFF | | innodb_buffer_pool_load_at_startup | OFF | | innodb_buffer_pool_load_now | OFF | | innodb_buffer_pool_size | 134217728 | + -------------------------------------+----------------+ Among those the most problematic one is the last parameter innodb_buffer_pool_size which is set to 128 MB only MySQL suggest that it should be set up to 80% of the machine's RAM. Unfortunately this parameter is NOT DYNAMIC for a version of the MariaDB service run inside the Qserv container: % mysql ... Server version: 10.1.21-MariaDB Source distribution The documentation suggests that the parameter is DYNAMIC as of verision 10.2.2 or higher. Therefore the only solution is to abort the index loading, reconfigure the service and resume the loading process from a file which takes to long to load. Aborting the loading: % ps -ef | grep load_ root 6142 1 0 Jun14 ? 00:00:00 /bin/sudo -u qserv /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash --verbose qserv 6144 6142 0 Jun14 ? 00:01:23 /bin/bash /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash --verbose gapon 18007 16017 0 16:16 pts /0 00:00:00 grep --color=auto load_ % sudo kill 6142 6144 Though, this didn't really kill the loading thread within the service as per: SHOW PROCESSLIST; | 64107 | root | localhost | NULL | Query | 10187 | reading file | LOAD DATA INFILE '/qserv/data/dumps/wise_2band_00/idx_object_200800.tsv' INTO TABLE qservMeta.wise_2 | 38.176 | Besides, the server is still running in then same node as earlier: % top top - 16:28:00 up 2 days, 6:17, 1 user, load average: 1.33, 1.39, 1.40 Tasks: 485 total, 1 running, 484 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.2 us, 0.1 sy, 0.0 ni, 97.7 id , 2.1 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 13128352+total, 440624 free , 2054096 used, 12878880+buff /cache KiB Swap: 4194300 total, 4103904 free , 90396 used. 12876192+avail Mem   PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 4806 qserv 20 0 3242864 255704 4808 S 9.6 0.2 732:49.71 mysqld ... Reconfiguring and restarting the service by logging into the Docker container: [gapon@lsst-qserv-master01 ~]$ docker exec -it qserv bash % export TERM=xterm % run /etc/init .d /mysqld help Usage: run /etc/init .d /mysqld {start|stop|restart|reload|force-reload|status} [ MySQL server options ] % mv run /etc/my .cnf run /etc/my .cnf.saved # added two parameters % diff run /etc/my .cnf run /etc/my .cnf.saved 18,20d17 < innodb_buffer_pool_size=96G < innodb_buffer_pool_instances=1   % run /etc/init .d /mysqld force-reload [ ok ] Reloading service MySQL.   # UNFORTUNATELY this did NOT stop the server   stop   # The previous operation was stuck as well. Killing the server process in the brute force way: % ps -ef qserv 90 1 0 Jun14 ? 00:00:00 /bin/sh /qserv/stack/Linux64/mariadb/10 .1.21.lsst1 /bin/mysqld_safe --defaults- file = /qserv/run/etc/my .cnf --datadir= /qserv/d qserv 210 90 23 Jun14 ? 12:14:16 /qserv/stack/Linux64/mariadb/10 .1.21.lsst1 /bin/mysqld --defaults- file = /qserv/run/etc/my .cnf --basedir= /qserv/stack/Linux64/ % kill -9 90 210   # Cleaning up the PID because of % run /etc/init .d /mysqld status [ ok ] MySQL running (27236).   % ls -al run /var/run/mysqld/ total 4 drwxr-xr-x 2 qserv qserv 23 Jun 16 16:47 . drwxr-xr-x 4 qserv qserv 99 Jun 14 11:39 .. -rw-rw---- 1 qserv qserv 6 Jun 16 16:47 mysqld.pid   % rm run /var/run/mysqld/mysqld .pid % run /etc/init .d /mysqld status [FAIL] MySQL is not running, but lock exists ... failed!   % ls -al run /var/lock/subsys/ total 0 drwxr-xr-x 2 qserv qserv 97 Jun 14 11:39 . drwxr-xr-x 3 qserv qserv 19 Apr 27 17:41 .. -rw-r--r-- 1 qserv qserv 0 Jun 14 11:39 cmsd -rw-r--r-- 1 qserv qserv 0 Jun 14 11:38 mysql -rw-r--r-- 1 qserv qserv 0 Jun 14 11:39 mysql-proxy -rw-r--r-- 1 qserv qserv 0 Jun 14 11:39 qserv-watcher -rw-r--r-- 1 qserv qserv 0 Jun 14 11:39 qserv-wmgr -rw-r--r-- 1 qserv qserv 0 Jun 14 11:39 xrootd % rm run /var/lock/subsys/mysql % run /etc/init .d /mysqld status [FAIL] MySQL is not running ... failed!   % run /etc/init .d /mysqld start Starting MySQL ............................................................................................................................................[....] Manager of pid- file quit[FAILout updating file . ... failed!   # However the database daemon seems to be back: % ps -ef UID PID PPID C STIME TTY TIME CMD ... qserv 27236 1 8 16:46 ? 00:01:53 /qserv/stack/Linux64/mariadb/10 .1.21.lsst1 /bin/mysqld --defaults- file = /qserv/run/etc/my .cnf --basedir= /qserv/stack/Linux64/ ... Testing the service and checking the new configuration from the host machine's shell: % top   top - 17:10:49 up 2 days, 6:59, 1 user, load average: 0.00, 0.10, 0.55 Tasks: 484 total, 1 running, 483 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.0 us, 0.0 sy, 0.0 ni,100.0 id , 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 13128352+total, 10918868 free , 11064664 used, 10929998+buff /cache KiB Swap: 4194300 total, 4107444 free , 86856 used. 11975208+avail Mem   PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19440 qserv 20 0 0.103t 8.846g 10148 S 0.3 7.1 1:53.85 mysqld NOTE : the new virtual size of the process. Checking the configuration parameters: SHOW PROCESSLIST; + ----+----------+-----------------+------------------+---------+------+-------+------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | + ----+----------+-----------------+------------------+---------+------+-------+------------------+----------+ | 2 | qsmaster | localhost | qservCssData | Sleep | 1 | | NULL | 0.000 | | 4 | qsmaster | localhost:38936 | sdss_stripe82_00 | Sleep | 1573 | | NULL | 0.000 | | 6 | qsmaster | localhost:38944 | sdss_stripe82_00 | Sleep | 193 | | NULL | 0.000 | | 10 | qsmaster | localhost:38954 | sdss_stripe82_00 | Sleep | 493 | | NULL | 0.000 | | 12 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST | 0.000 | + ----+----------+-----------------+------------------+---------+------+-------+------------------+----------+ SHOW VARIABLES LIKE 'innodb_buffer_pool_%' ; + -------------------------------------+----------------+ | Variable_name | Value | + -------------------------------------+----------------+ | innodb_buffer_pool_dump_at_shutdown | OFF | | innodb_buffer_pool_dump_now | OFF | | innodb_buffer_pool_dump_pct | 100 | | innodb_buffer_pool_filename | ib_buffer_pool | | innodb_buffer_pool_instances | 1 | | innodb_buffer_pool_load_abort | OFF | | innodb_buffer_pool_load_at_startup | OFF | | innodb_buffer_pool_load_now | OFF | | innodb_buffer_pool_size | 103079215104 | + -------------------------------------+----------------+ Resuming the index loading Test the number of objects in the secondary index table:   Checking the index loading status: % ls -al /tmp/wise_2band_00/log/ | grep load_idx | tail -4 -rw-r--r-- 1 qserv qserv 0 Jun 16 11:35 load_idx_object_200797.tsv.log -rw-r--r-- 1 qserv qserv 0 Jun 16 11:47 load_idx_object_200798.tsv.log -rw-r--r-- 1 qserv qserv 0 Jun 16 12:18 load_idx_object_200799.tsv.log -rw-r--r-- 1 qserv qserv 58 Jun 16 16:33 load_idx_object_200800.tsv.log   % cat /tmp/wise_2band_00/log/load_idx_object_200800 .tsv.log ERROR 1053 (08S01) at line 1: Server shutdown in progress This is the DESIRED result meaning that loading of the last TSV file was aborted and trasaction was rolled back which is also supported by this message in the server's log file: % sudo cat /qserv/log/mysqld .log ... 170616 16:56:43 mysqld_safe mysqld from pid file /qserv/run/var/run/mysqld/mysqld .pid ended 94 95 96 97 98 99 1002017-06-16 16:57:18 140284848981760 [Note] InnoDB: Rollback of trx with id 118618240 completed 2017-06-16 16:57:18 7f969c974700 InnoDB: Rollback of non-prepared transactions completed 170616 17:03:25 mysqld_safe Starting mysqld daemon with databases from /qserv/data/mysql ... Making sure the new loading won't destroy the previously loaded content. This is the SQL DML statement which create the table: % cat /tmp/wise_2band_00/create_secondary_index .sql CREATE TABLE IF NOT EXISTS `qservMeta`.`wise_2band_00__allsky_2band_p1bs_psd` ( `source_id` CHAR (28) NOT NULL , `chunkId` int (11) DEFAULT NULL , `subChunkId` int (11) DEFAULT NULL , PRIMARY KEY (`source_id`) ) ENGINE=InnoDB DEFAULT CHARSET=latin1; Putting away TSV files which were successfully loaded as per the master log file: % /bin/sudo -u qserv mkdir /qserv/data/dumps/wise_2band_00/loaded % for f in ` cat load_secondary_index.log | grep loading | awk '{print $5}' `; do echo mv \ /qserv/data/dumps/wise_2band_00/ ${f} \ /qserv/data/dumps/wise_2band_00/loaded/ ${f} done | wc -l 63104     % for f in ` cat load_secondary_index.log | grep loading | awk '{print $5}' `; do echo mv \ /qserv/data/dumps/wise_2band_00/ ${f} \ /qserv/data/dumps/wise_2band_00/loaded/ ${f} done | tail -3 mv /qserv/data/dumps/wise_2band_00/idx_object_200798 .tsv /qserv/data/dumps/wise_2band_00/loaded/idx_object_200798 .tsv mv /qserv/data/dumps/wise_2band_00/idx_object_200799 .tsv /qserv/data/dumps/wise_2band_00/loaded/idx_object_200799 .tsv mv /qserv/data/dumps/wise_2band_00/idx_object_200800 .tsv /qserv/data/dumps/wise_2band_00/loaded/idx_object_200800 .tsv And now move the files for real ( NOTE we should put the last file idx_object_200800.tsv back because it was not properly loaded while the process was aborted): % for f in ` cat load_secondary_index.log | grep loading | awk '{print $5}' `; do echo $f /bin/sudo -u qserv mv /qserv/data/dumps/wise_2band_00/ ${f} \ /qserv/data/dumps/wise_2band_00/loaded/ ${f} done % /bin/sudo -u qserv \ mv /qserv/data/dumps/wise_2band_00/loaded/idx_object_200800 .tsv \ /qserv/data/dumps/wise_2band_00/   % /bin/sudo -u qserv \ ls -1 /qserv/data/dumps/wise_2band_00/loaded | grep .tsv | wc -l 63103   % /bin/sudo -u qserv \ ls -1 /qserv/data/dumps/wise_2band_00/ | grep .tsv | wc -l 43788 Saved the previous log file and restarted the operation: % mv load_secondary_index.log load_secondary_index.log.loaded % nohup /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose >& load_secondary_index.log& Table size: % sudo ls -alh /qserv/data/mysql/qservMeta/ | grep wise_2band_00 -rw-rw---- 1 qserv qserv 1014 Jun 14 12:02 wise_2band_00__allsky_2band_p1bs_psd.frm -rw-rw---- 1 qserv qserv 334G Jun 16 18:36 wise_2band_00__allsky_2band_p1bs_psd.ibd Disk space status: % df -h / Filesystem Size Used Avail Use% Mounted on /dev/mapper/system-root 926G 733G 194G 80% / ATTENTION : The previously loaded files may need to be removed to free some space of needed: % /bin/sudo -u qserv \ du -hs /qserv/data/dumps/wise_2band_00/loaded 94G /qserv/data/dumps/wise_2band_00/loaded   % /bin/sudo -u qserv \ du -hs /qserv/data/dumps/wise_2band_00/ 187G /qserv/data/dumps/wise_2band_00/ Monitoring the loading process to see if the new configuration has allowed to speed it up: % top   top - 18:32:22 up 2 days, 8:21, 1 user, load average: 1.23, 0.61, 0.34 Tasks: 487 total, 1 running, 486 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.2 us, 0.1 sy, 0.0 ni, 97.7 id , 2.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 13128352+total, 10661044 free , 11181256 used, 10944121+buff /cache KiB Swap: 4194300 total, 4107444 free , 86856 used. 11955263+avail Mem   PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19440 qserv 20 0 0.103t 8.945g 10412 S 11.0 7.1 2:36.26 mysqld % iostat -k 10 ... avg-cpu: %user % nice %system %iowait %steal %idle 0.23 0.00 0.06 1.39 0.00 98.33   Device: tps kB_read /s kB_wrtn /s kB_read kB_wrtn sda 184.10 0.00 10396.05 0 103960 dm-0 183.60 0.00 10378.45 0 103784   avg-cpu: %user % nice %system %iowait %steal %idle 0.22 0.00 0.06 1.44 0.00 98.28   Device: tps kB_read /s kB_wrtn /s kB_read kB_wrtn sda 189.00 0.00 11197.50 0 111975 dm-0 189.10 0.00 11200.70 0 112007 ... The last operation HAS FAILED due to disk space limitation. At this point the loading was stopped and a major upgrade of the master node hardware ordered as per JIRA [IHS-378] . The second attempt to generate the secondary index after the hardware upgrade NOTE : this attempt will also involve an additional step of presorting the contents of the TSV triplet files before loading them into the table. The main benefit of this is a significant table size reduction as demonstrated in DM-11027 (jump straight to the Conclusions section). Verifying the status of the secondary index generation and cleaning it up Compare the total number of loaded Objects versus the number of entries in the incomplete secondary index. Obtaining the total number of loaded objects via Qserv proxy : SELECT COUNT (*) FROM wise_2band_00.allsky_2band_p1bs_psd; + ----------------+ | SUM (QS1_COUNT) | + ----------------+ | 7337642955 | + ----------------+ 1 row in set (8 min 55.40 sec) Obtaining the number of the secondary index entries via a direct connection to the master's MySQL service: SELECT COUNT (*) FROM qservMeta.wise_2band_00__allsky_2band_p1bs_psd; + ------------+ | COUNT (*) | + ------------+ | 6738261333 | + ------------+ NOTE :' it took about 3 hours to get the result of the query. Wipe out the secondary index: DROP TABLE qservMeta.wise_2band_00__allsky_2band_p1bs_psd; Query OK, 0 rows affected (40.67 sec) Get rid of the local ( master ) cache of the intermediate TSV files: % /bin/sudo -u qserv rm -rvf /qserv/data/dumps/wise_2band_00 % /bin/sudo -u qserv mkdir /qserv/data/dumps/wise_2band_00 Pulling triplets from the worker nodes to master ATTENTION : this operation is based on an assumption that all triplets which were created during the first (the failed) attempt were still available. And indeed this was verified prior to proceed with this stage. Details are not going to be reflected here. Harvesting triplets: % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_dump_triplet . bash \ --verbose \ >& run_dump_triplet.log& Verify if the dump completed on all worker nodes: Loading triplets into the index: % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose \ --get-remote-triplets \ --no-triplets-loading \ >& pull_triplets.log& Verifying a status of triplets after the file migration operation finished. Verifying if the total number of TSV fils matched the number of partitions: % ls -1 /qserv/data/dumps/wise_2band_00 | grep tsv | wc -l 106891 Verifying if the total number of objects matches expectations (the actual counting was a bit more complex because the shell interpreter was not able to expand the list of 106891 files): % wc -l /qserv/data/dumps/wise_2band_00/ *.tsv 7337642955 CONCLUSION : bot numbers match the expectations. Pre-sorting and merging TSV files NOTE : This stage is required due to the 30% reduction of the table size demonstrated in DM-11027 . Also, the sort-merge has no significant effect on the total duration of the procedure. Creating 64 groups of TSV files which will be processed in parallel (because the second soft-merge procedure is CPU intensive): % /bin/sudo -u qserv -i % cd /qserv/data/dumps/ % mkdir wise_2band_00_tsv64 % ls wise_2band_00 | grep tsv > wise_2band_00_tsv64.txt % wc -l wise_2band_00_tsv64.txt 106891 wise_2band_00_tsv64.txt % cd wise_2band_00_tsv64 % split -d -l 1674 .. /wise_2band_00_tsv64 .txt '' % ls -l % ls -al | head -4 -rw-rw-r-- 1 qserv qserv 36809 Oct 27 15:42 00 ... -rw-rw-r-- 1 qserv qserv 35141 Oct 27 15:42 62 -rw-rw-r-- 1 qserv qserv 30009 Oct 27 15:42 63 % wc -l * | tail -1 106891 total Sort in 64 streams and store the sorted files in a separate folder: % cd /qserv/data/dumps/ % mkdir wise_2band_00_sorted % ate Fri Oct 27 15:46:06 CDT 2017 % for c in ` ls wise_2band_00_tsv64`; do for f in ` cat wise_2band_00_tsv64/${c}`; do sort wise_2band_00/${f} > wise_2band_00_sorted/${f} done & done Analyzing results after all 64 jobs finished: % date Fri Oct 27 16:25:52 CDT 2017 % ls -1 wise_2band_00_sorted | wc -l 106891 % du -hs wise_2band_00_sorted 187G wise_2band_00_sorted Total run time of the stage: 40 min The next step is to do the merge-sort. Due to a large number of input files this operation is split into 2 steps: sort-merging files within each stream (as defined on the previous step). All 64 streams are processed simulnateously. final merge of the 64 files (produced by the previous stage) into a single file Parallel merge of 64 streams: % cd wise_2band_00_sorted % mkdir .. /wise_2band_00_sorted_merged % for f in ` ls .. /wise_2band_00_tsv64 `; do mkdir -p .. /wise_2band_00_tmp_ ${f} cat .. /wise_2band_00_tsv64/ ${f} | tr '\n' '\0' | sort -m -s -k1 -T .. /wise_2band_00_tmp_ ${f} -o .. /wise_2band_00_sorted_merged/ ${f}.tsv --files0-from=- & done % date Fri Oct 27 17:54:27 CDT 2017 NOTE: the translation of newlines to NULL is required to feed null-terminated file (input) names into the sort tool. Also note that each stream uses its own temporary directory on the current disk instead of relying on a small /tmp file system. Analyzing a status after it finished % date Fri Oct 27 18:16:33 CDT 2017 % ls -1 wise_2band_00_sorted_merged/ | wc -l 64 % du -hs wise_2band_00_sorted_merged/ 187G wise_2band_00_sorted_merged/ % wc -l wise_2band_00_sorted_merged/*.tsv | tail -1 7337642955 total Total run time of the stage: 22 minutes Final merge of 64 steam files into the large one: % mkdir wise_2band_00_tmp % nohup sort -m -s -k1 -T wise_2band_00_tmp/ -o wise_2band_00_sorted_merged.tsv wise_2band_00_sorted_merged/*& % date Fri Oct 27 18:42:34 CDT 2017 Analyzing a status after it finished % date Fri Oct 27 20:47:04 CDT 2017 % ls -alh wise_2band_00_sorted_merged.tsv -rw-rw-r-- 1 qserv qserv 187G Oct 27 20:41 wise_2band_00_sorted_merged.tsv % wc -l wise_2band_00_sorted_merged.tsv 7337642955 wise_2band_00_sorted_merged.tsv Total run time of the stage: 2 hours Splitting the large file into smaller chunks % mkdir wise_2band_00_sorted_merged_split % cd wise_2band_00_sorted_merged_split % date Fri Oct 27 20:52:56 CDT 2017 % split -d -l 80663508 .. /wise_2band_00_sorted_merged .tsv '' % date Fri Oct 27 20:59:36 CDT 2017 Analyzing a status after it finished % ls -1 | wc -l 91 % du -hs . 187G . % wc -l * | tail -1 7337642955 total Total number of files: 91 Average file size: 2.2 GB Lines per file: 80663508 Total run time of the stage: 7 minutes Rename folders and those lastly created 91 TSV files to allow the previously developed tool to work: % mv wise_2band_00 wise_2band_00_imported % ln -s wise_2band_00_sorted_merged_split wise_2band_00 % cd wise_2band_00_sorted_merged_split % for f in ` ls `; do mv ${f} ${f}.tsv; done   Loading: {code: bash } % cd /home/gapon % date Fri Oct 27 21:27:06 CDT 2017 % nohup /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose \ >& load_secondary_index_load_only.log& Monitoring the progress: % iostat -m 1 | grep sdb sdb 123.12 5.44 5.93 1444284 1573500 sdb 489.00 6.75 93.35 6 93 sdb 583.00 7.75 110.45 7 110 sdb 395.00 8.00 74.53 8 74 sdb 554.00 4.50 104.20 4 104 sdb 626.00 8.50 120.70 8 120 sdb 794.00 7.62 165.61 7 165 sdb 575.00 10.00 109.70 10 109 sdb 755.00 9.62 143.21 9 143 ...   % sudo ls -alh /qserv/data/mysql/qservMeta | grep wise_2band_00 -rw-rw---- 1 qserv qserv 1014 Oct 27 03:40 wise_2band_00__allsky_2band_p1bs_psd.frm -rw-rw---- 1 qserv qserv 6.3G Oct 27 21:33 wise_2band_00__allsky_2band_p1bs_psd.ibd The operation finished within less than 7 hours . The log files are unremarkable. The row count matches the number of objects in tables: SELECT COUNT (*) FROM qservMeta.wise_2band_00__allsky_2band_p1bs_psd; + ------------+ | COUNT (*) | + ------------+ | 7337642955 | + ------------+ The size of the table files is: % sudo ls -alh /qserv/data/mysql/qservMeta | grep wise_2band_00 -rw-rw---- 1 qserv qserv 1014 Oct 27 03:40 wise_2band_00__allsky_2band_p1bs_psd.frm -rw-rw---- 1 qserv qserv 416G Oct 28 04:22 wise_2band_00__allsky_2band_p1bs_psd.ibd Cleaning up: % rm wise_2band_00_tsv64.txt % rm -rf wise_2band_00_tsv64/ % rm -rf wise_2band_00 % rm -rf wise_2band_00_sorted/ % rm -rf wise_2band_00_sorted_merged/ % rm -rf wise_2band_00_tmp*/ % rm wise_2band_00_sorted_merged.tsv % rm -rf wise_2band_00_sorted_merged_split/ % rm wise_2band_00 % rm -rf wise_2band_00 wise_2band_00_imported/ % mkdir wise_2band_00   % df -h /data Filesystem Size Used Avail Use% Mounted on /dev/sdb1 2.7T 617G 2.1T 24% /data Setting up the empty chunk list file The file was generated using the trivial Python script based on early produced list of unique chunks: chunks = {} with open ( "all_chunks_unique_sorted.txt" , "r" ) as f: for chunk in f: chunks[ int (chunk[: - 1 ])] = True   minChunk = 0 maxChunk = 1000000 for chunk in range (minChunk,maxChunk): if chunk not in chunks: print chunk The generator was used like this: % cd /datasets/gapon/wise/allsky_2band_p1bs_psd/partitioned_x16 % python generate_empty_chunk_list.py > empty_wise_2band_00.txt % wc -l empty_wise_2band_00.txt 893059 empty_wise_2band_00.txt % wc -l all_chunks_unique_sorted.txt 106941 all_chunks_unique_sorted.txt Then installed the resulting files on the master node: % /bin/sudo -u qserv \ cp /datasets/gapon/wise/allsky_2band_p1bs_psd/partitioned_x16/empty_wise_2band_00 .txt \ /qserv/data/qserv/ Enabling the database in Qserv % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_qserv_enable_database . bash \ --verbose \ >& run_qserv_enable_database.log& ATTENTION : Qserv needs to be restarted to recognize the database

Igor Gaponenko added a comment - 05/Nov/17 12:19 PM - edited Loading catalog allsky_4band_p1bs_psd into PDAC The loading protocol is explained in details at: https://confluence.lsstcorp.org/display/DM/Loading+WISE+catalogs+into+PDAC The rest of this section presents a short summary of actions and tests taken during this loading. Dataset configuration Database name: wise_4band_00 Do this at lsat-dev: % cd /datasets/gapon/development/db_pdac_wise/scripts % ln -s dataset. bash .wise_4band_00 dataset. bash Creating database and initializing CSS All these steps were conducted on the master node of the cluster lsst-qserv-master01 : % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_create_database . bash \ --delete --verbose >& run_create_database.log&   % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/setup_css . bash \ >& setup_css.log % source /datasets/gapon/stack/loadLSST . bash % setup -t qserv-dev qserv_distrib; setup -j -r /datasets/gapon/development/qserv % qserv-admin.py "DUMP EVERYTHING;" | grep wise_4band_00 /DBS/wise_4band_00 READY /DBS/wise_4band_00/ .packed.json { "partitioningId" : "0000000029" , "releaseStatus" : "RELEASED" , "storageClass" : "L2" } /DBS/wise_4band_00/TABLES \N /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd READY /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd/partitioning \N /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd/partitioning/ .packed.json { "dirColName" : "source_id" , "dirDb" : "wise_4band_00" , "dirTable" : "allsky_4band_p1bs_psd" , "latColName" : "decl" , "lonColName" : "ra" , "subChunks" : "1" } /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd/schema ( /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd/sharedScan \N /DBS/wise_4band_00/TABLES/allsky_4band_p1bs_psd/sharedScan/ .packed.json { "lockInMem" : "1" } Configuring MySQL server and Docker container These actions are required to ensure each worker is properly configured. See loading protocol for other n-band protocol for details. Loading partitioned tables % nohup /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_load_object . bash \ --verbose \ >& run_load_object.log& Testing results: % for f in ` ls /tmp/wise_4band_00/log/qserv-db *_load_object.log`; do tail -1 $f; done [Sat Nov 18 18:29:21 CST 2017] ** Finished loading ** [Sat Nov 18 18:12:13 CST 2017] ** Finished loading ** .. % for f in ` ls /tmp/wise_4band_00/log/qserv-db *_load_object.log`; do tail -1 $f; done | wc -l 30 Generating the secondary index Harvesting triplets % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_dump_triplet . bash \ --verbose \ >& run_dump_triplet.log& Inspect log files and cross-check the number of per-worker chunks against the number of success reports in the log files: % for n in ` seq -- format "qserv-db%02.f" 1 30`; do ssh -n $n 'wc -l /tmp/wise_4band_00/chunks.txt; tail /tmp/wise_4band_00/log/dump_triplet.* | grep Finished | wc -l' 4878 /tmp/wise_4band_00/chunks .txt 4878 4878 /tmp/wise_4band_00/chunks .txt 4878 .. 4877 /tmp/wise_4band_00/chunks .txt 4877 done Pulling triplets from the worker nodes to master Pulling triplet files from all worker nodes into the master w/o loading them: % nohup \ /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose \ --get-remote-triplets \ --no-triplets-loading \ >& pull_triplets.log& When the loading finished, inspected results to see if the number of TSV files matches expectations: % wc -l /datasets/gapon/wise/allsky_4band_p1bs_psd/partitioned_x16/all_chunks_unique_sorted .txt 146332 /datasets/gapon/wise/allsky_4band_p1bs_psd/partitioned_x16/all_chunks_unique_sorted .txt % sudo ls /qserv/data/dumps/wise_4band_00/ | grep tsv | wc -l 146332 % /bin/sudo -u qserv du -hs /qserv/data/dumps/wise_4band_00/ 242G /qserv/data/dumps/wise_4band_00/ Pre-sorting and merging TSV files NOTE : This stage is required due to the 30% reduction of the table size demonstrated in DM-11027 . Also, the sort-merge has no significant effect on the total duration of the procedure. Creating 88 groups of TSV files which will be processed in parallel (because the second soft-merge procedure is CPU intensive): % /bin/sudo -u qserv -i % cd /qserv/data/dumps/ % mkdir wise_4band_00_tsv64 % ls wise_4band_00 | grep tsv > wise_4band_00_tsv64.txt % wc -l wise_4band_00_tsv64.txt 146332 wise_4band_00_tsv64.txt % cd wise_4band_00_tsv64 % split -d -l 1674 .. /wise_4band_00_tsv64 .txt '' % ls -1 | wc -l 88 % wc -l * | tail -1 146332 total Sort in 88 streams and store the sorted files in a separate folder: % cd /qserv/data/dumps/ % mkdir wise_4band_00_sorted % for c in ` ls wise_4band_00_tsv64`; do for f in ` cat wise_4band_00_tsv64/${c}`; do sort wise_4band_00/${f} > wise_4band_00_sorted/${f} done & done Analyzing results after all 88 jobs finished: % date % ls -1 wise_4band_00_sorted | wc -l 146332 % du -hs wise_4band_00_sorted 242G wise_4band_00_sorted The next step is to do the merge-sort. Due to a large number of input files this operation is split into 2 steps: sort-merging files within each stream (as defined on the previous step). All 88 streams are processed simultaneously. final merge of the 88 files (produced by the previous stage) into a single file Parallel merge of 88 streams: % cd wise_4band_00_sorted % mkdir .. /wise_4band_00_sorted_merged % for f in ` ls .. /wise_4band_00_tsv64 `; do mkdir -p .. /wise_4band_00_tmp_ ${f} cat .. /wise_4band_00_tsv64/ ${f} | tr '\n' '\0' | sort -m -s -k1 -T .. /wise_4band_00_tmp_ ${f} -o .. /wise_4band_00_sorted_merged/ ${f}.tsv --files0-from=- & done NOTE: the translation of newlines to NULL is required to feed null-terminated file (input) names into the sort tool. Also note that each stream uses its own temporary directory on the current disk instead of relying on a small /tmp file system. Analyzing a status after it finished % ls -1 wise_4band_00_sorted_merged/ | wc -l 88 % du -hs wise_4band_00_sorted_merged/ 241G .. /wise_4band_00_sorted_merged % wc -l wise_4band_00_sorted_merged/*.tsv | tail -1 All 88 files has reasonable content in their last lines. Final merge of 88 steam files into the large one: % mkdir wise_4band_00_tmp % nohup sort -m -s -k1 -T wise_4band_00_tmp/ -o wise_4band_00_sorted_merged.tsv wise_4band_00_sorted_merged/*& Analyzing a status after it finished % ls -alh wise_4band_00_sorted_merged.tsv -rw-rw-r-- 1 qserv qserv 241G Nov 20 18:49 wise_4band_00_sorted_merged.tsv % wc -l wise_4band_00_sorted_merged.tsv 9479433101 wise_4band_00_sorted_merged.tsv Splitting the large file into smaller chunks % mkdir wise_4band_00_sorted_merged_split % cd wise_4band_00_sorted_merged_split % split -d -l 148116143 .. /wise_4band_00_sorted_merged .tsv '' Analyzing a status after it finished % ls -1 | wc -l % du -hs . 241G . % wc -l * | tail -1 9479433101 total Total number of files: 64 Average file size: 3.8 GB Lines per file: 148M Rename folders and those lastly created NN TSV files to allow the previously developed tool to work: % mv wise_4band_00 wise_4band_00_imported % ln -s wise_4band_00_sorted_merged_split wise_4band_00 % cd wise_4band_00_sorted_merged_split % for f in ` ls `; do mv ${f} ${f}.tsv; done Loading: % cd /home/gapon % nohup /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/load_secondary_index . bash \ --verbose \ >& load_secondary_index_load_only.log& When finished % /bin/sudo -u qserv ls -alh /qserv/data/mysql/qservMeta | grep wise_4band_00 -rw-rw---- 1 qserv qserv 1014 Nov 19 21:28 wise_4band_00__allsky_4band_p1bs_psd.frm -rw-rw---- 1 qserv qserv 537G Nov 21 04:21 wise_4band_00__allsky_4band_p1bs_psd.ibd The log files are unremarkable. The row count matches the number of objects in tables: SELECT COUNT (*) FROM qservMeta.wise_4band_00__allsky_4band_p1bs_psd; 9479433101 Cleaning up: % cd /qserv/data/dumps % df -h /data Setting up the empty chunk list file The file was generated using the trivial Python script based on early produced list of unique chunks: chunks = {} with open ( "all_chunks_unique_sorted.txt" , "r" ) as f: for chunk in f: chunks[ int (chunk[: - 1 ])] = True   minChunk = 0 maxChunk = 1000000 for chunk in range (minChunk,maxChunk): if chunk not in chunks: print chunk The generator was used like this: % cd /datasets/gapon/wise/allsky_4band_p1bs_psd/partitioned_x16 % python generate_empty_chunk_list.py > empty_wise_4band_00.txt % wc -l empty_wise_4band_00.txt 853668 empty_wise_4band_00.txt % wc -l all_chunks_unique_sorted.txt 146332 all_chunks_unique_sorted.txt Then installed the resulting files on the master node: % /bin/sudo -u qserv \ cp /datasets/gapon/wise/allsky_4band_p1bs_psd/partitioned_x16/empty_wise_4band_00 .txt \ /qserv/data/qserv/ Enabling the database in Qserv % /bin/sudo -u qserv \ /datasets/gapon/development/db_pdac_wise/scripts/run_qserv_enable_database . bash \ --verbose \ >& run_qserv_enable_database.log& ATTENTION : Qserv needs to be restarted to recognize the database Testing Testing the number of objects returned by the shared scan query versus the one reported from the secondary index : SELECT COUNT (*) FROM wise_4band_00.allsky_4band_p1bs_psd; + ----------------+ | SUM (QS1_COUNT) | + ----------------+ | 9479433101 | + ----------------+ 1 row in set (11 min 24.86 sec) CONCLUSION : the numbers matches the number of the secondary index entries.

Igor Gaponenko added a comment - 21/Nov/17 3:49 PM All three catalogs have been successfully loaded. Proceeding to DM-12523 .

Fritz Mueller added a comment - 21/Nov/17 4:16 PM Woohoo!!