(Clover) Stress Test 2: Flat to MySQL

The Second stress test involves, Pass 6 millions of records from a Flat File, to a table in MySQL.


As in most of the Test, there are several cases using differents techniques, setting of variables, with the same objective, satisfy the requirement and improve the performance. Always the first case is the best, and the rest of cases, are jobs that don't have the most appropiate set up options, but helped in the way to reach the goal of improving performance.

LINKS

CASE 1 [3882 Secs.]

CASE 2 [4647 Secs.]

CASE 3 [6808 Secs.]

CASE 1: MySQL in other VM + -server + Xmx=1500 + 100K CommitSize

Objective: To measure elapsed time reading and writing 6 million rows, from Flat file, to a MySQL database. In this case (case 1), the database run in the same virtual machine, therefore, Clover & DB share the disk (key point), but the MySQL Service consume CPU.
Rows: 6.024.000 M
Columns: 37 Columns
Resources: Virtual machine with: 2 GB RAM, Clover & MySQL like main process over the virtual plataform. The resources used are anecdotal, today, Any production environment has enough processing power for current and future requirements. The objective here, is to build, to execute and to measure with the same environment (regardless of the limited resources)
Structure:
Design & Run
Elapsed time (s) 3882 sec.
How to Improve Perform.

- Change Commit Size to 100.000 r/ (for this case)

- Use ServerMode

- Change -Xmx to 1.500MB

Summary of log
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:54:50
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 5967619 1515374 1861 467
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 5967619 1515374 1861 467
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:54:55
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 5974024 1516984 1272 319
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 5974024 1516984 1272 319
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:00
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 5982780 1519183 1728 434
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 5982780 1519183 1728 434
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:05
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 5988841 1520706 1204 302
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 5988841 1520706 1204 302
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:10
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 5995917 1522483 1410 354
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 5995917 1522483 1410 354
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:15
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 6003674 1524430 1518 381
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 6003674 1524430 1518 381
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:20
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 6015137 1527307 2288 574
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 6015137 1527307 2288 574
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 08/03/12 13:55:25
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.05 Out:0 6022839 1529241 1534 385
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.14 In:0 6022839 1529241 1534 385
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - [Clover] Post-execute phase finalization: 0
INFO [WatchDog] - [Clover] phase: 0 post-execute finalization successfully.
INFO [WatchDog] - ----------------------** Final tracking Log for phase [0] **---------------------
INFO [WatchDog] - Time: 08/03/12 13:55:29
INFO [WatchDog] - Node ID Port #Records #KB aRec/s aKB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 FINISHED_OK
INFO [WatchDog] - %cpu:0.05 Out:0 6029426 1530895 1553 394
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 FINISHED_OK
INFO [WatchDog] - %cpu:0.21 In:0 6029426 1530895 1553 394
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - Execution of phase [0] successfully finished - elapsed time(sec): 3881
INFO [WatchDog] - Post-execute finalization of connection:
INFO [WatchDog] - DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriver@6b93c5]:jndi[null]:url[jdbc:mysql://192.168.0.114:3306/world]:user[root] ... OK
INFO [WatchDog] - -----------------------** Summary of Phases execution **---------------------
INFO [WatchDog] - Phase# Finished Status RunTime(sec) MemoryAllocation(KB)
INFO [WatchDog] - 0 FINISHED_OK 3881 15791
INFO [WatchDog] - ------------------------------** End of Summary **---------------------------
INFO [WatchDog] - WatchDog thread finished - total execution time: 3882 (sec)
INFO [main] - Freeing graph resources.
INFO [main] - Execution of graph successful !

CASE 2: MySQL in the Same VM (excepcional case) + without -server + Xmx=0

Objective: To measure elapsed time reading and writing 6 million rows, from Flat file, to a MySQL database. In this case (case 1), the database runs in the same virtual machine, therefore, Clover & DB share the disk (key point), but the MySQL Service consume CPU.
Rows: 6.024.000 M
Columns: 37 Columns
Resources: Virtual machine with: 2 GB RAM, Clover & MySQL like main process over the virtual plataform. The resources used are anecdotal, today, Any production environment has enough processing power for current and future requirements. The objective here, is to build, to execute and to measure with the same environment (regardless of the limited resources)
Structure:
Design & Run
Elapsed time (s) 4647 sec.
Rows per sec (avg)

Here, show the evolution of the passage of rows via the transformations, each 5 seconds.

1.469 rows/sec

% cpu

Node reader: 0,04 % a 0,05%

Node writer: 0,21% a 0,22%

Summary of log INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 22/02/12 19:04:30
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.04 Out:0 5984798 1519690 2250 565
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.21 In:0 5984798 1519690 2250 565
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 22/02/12 19:04:35
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.04 Out:0 5996926 1522737 2400 602
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.21 In:0 5996926 1522737 2400 602
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 22/02/12 19:04:40
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.04 Out:0 6007045 1525276 2014 505
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.21 In:0 6007045 1525276 2014 505
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 22/02/12 19:04:45
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.04 Out:0 6018173 1528069 2189 549
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.21 In:0 6018173 1528069 2189 549
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 22/02/12 19:04:50
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.04 Out:0 6024239 1529592 1203 302
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.21 In:0 6024239 1529592 1203 302
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - [Clover] Post-execute phase finalization: 0
INFO [WatchDog] - [Clover] phase: 0 post-execute finalization successfully.
INFO [WatchDog] - ----------------------** Final tracking Log for phase [0] **---------------------
INFO [WatchDog] - Time: 22/02/12 19:04:53
INFO [WatchDog] - Node ID Port #Records #KB aRec/s aKB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 FINISHED_OK
INFO [WatchDog] - %cpu:0.05 Out:0 6029426 1530895 1298 329
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 FINISHED_OK
INFO [WatchDog] - %cpu:0.22 In:0 6029426 1530895 1298 329
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - Execution of phase [0] successfully finished - elapsed time(sec): 4642
INFO [WatchDog] - Post-execute finalization of connection:
INFO [WatchDog] - DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriver@156b386]:jndi[null]:url[jdbc:mysql://localhost:3306/world]:user[root] ... OK
INFO [WatchDog] - -----------------------** Summary of Phases execution **---------------------
INFO [WatchDog] - Phase# Finished Status RunTime(sec) MemoryAllocation(KB)
INFO [WatchDog] - 0 FINISHED_OK 4642 11024
INFO [WatchDog] - ------------------------------** End of Summary **---------------------------
INFO [WatchDog] - WatchDog thread finished - total execution time: 4647 (sec)
INFO [main] - Freeing graph resources.
INFO [main] - Execution of graph successful !

CASE 3: MySQL in the other VM + without -server + Xmx=0

Objective: To measure elapsed time reading and writing 6 million rows, from Flat file, to a MySQL database. In this case (case 2), the database run in other machine. The benefit es "Clear", only Clover run alone in the virtual machine. The negative point is the transfer of data through the network, using the generic drivers installed by VM.
Rows: 6.024.000 M
Columns: 37 Columns
Resources: Virtual machine with: 2 GB RAM, Clover like main process over the virtual plataform. The resources used are anecdotal, today, Any production environment has enough processing power for current and future requirements. The objective here, is use and to measure with the same environment (regardless of the limited resources)
Structure:
Design & Run
Elapsed time (s) 6808 sec.
Rows per sec (avg)

Here, show the evolution of the passage of rows via the transformations, each 5 seconds.

958 rows/sec

% cpu

Node reader: 0,03 % a 0,04%

Node writer: 0,04% a 0,06%

Summary of log INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 5998952 1523245 1153 289
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 5998952 1523245 1153 289
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:11
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6004007 1524514 1007 253
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6004007 1524514 1007 253
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:16
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6008055 1525530 806 202
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6008055 1525530 806 202
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:21
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6012103 1526545 806 202
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6012103 1526545 806 202
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:26
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6017160 1527815 1008 253
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6017160 1527815 1008 253
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:31
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6022218 1529085 1008 253
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6022218 1529085 1008 253
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - ---------------------** Start of tracking Log for phase [0] **-------------------
INFO [WatchDog] - Time: 23/02/12 11:58:36
INFO [WatchDog] - Node ID Port #Records #KB Rec/s KB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 RUNNING
INFO [WatchDog] - %cpu:0.03 Out:0 6027271 1530354 1007 253
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 RUNNING
INFO [WatchDog] - %cpu:0.04 In:0 6027271 1530354 1007 253
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - [Clover] Post-execute phase finalization: 0
INFO [WatchDog] - [Clover] phase: 0 post-execute finalization successfully.
INFO [WatchDog] - ----------------------** Final tracking Log for phase [0] **---------------------
INFO [WatchDog] - Time: 23/02/12 11:58:41
INFO [WatchDog] - Node ID Port #Records #KB aRec/s aKB/s
INFO [WatchDog] - ---------------------------------------------------------------------------------
INFO [WatchDog] - UniversalDataReader DATA_READER0 FINISHED_OK
INFO [WatchDog] - %cpu:0.04 Out:0 6029426 1530895 885 224
INFO [WatchDog] - DBOutputTable DB_OUTPUT_TABLE0 FINISHED_OK
INFO [WatchDog] - %cpu:0.06 In:0 6029426 1530895 885 224
INFO [WatchDog] - ---------------------------------** End of Log **--------------------------------
INFO [WatchDog] - Execution of phase [0] successfully finished - elapsed time(sec): 6808
INFO [WatchDog] - Post-execute finalization of connection:
INFO [WatchDog] - DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriver@95215b]:jndi[null]:url[jdbc:mysql://192.168.0.109:3306/world]:user[root] ... OK
INFO [WatchDog] - -----------------------** Summary of Phases execution **---------------------
INFO [WatchDog] - Phase# Finished Status RunTime(sec) MemoryAllocation(KB)
INFO [WatchDog] - 0 FINISHED_OK 6808 12148
INFO [WatchDog] - ------------------------------** End of Summary **---------------------------
INFO [WatchDog] - WatchDog thread finished - total execution time: 6808 (sec)
INFO [main] - Freeing graph resources.
INFO [main] - Execution of graph successful !