search

datavane / tis

Support agile DataOps Based on Flink, DataX and Flink-CDC, Chunjun with Web-UI
https://tis.pub
Apache License 2.0
1.04k stars 221 forks source link

使用 JFR（JAVA FlightRecorder）性能调优批量导入执行流程 #313

Open baisui1981 opened 7 months ago

baisui1981 commented 7 months ago

在执行MySQL->MySQL 的pipeline管道同步流程中发现日志中，某几次打印流量同步的数据量为0，如下：

2024-04-20 11:43:56 INFO  c.a.d.p.r.r.CommonRdbmsReader$Task- Begin to read record by Sql: [select `instance_id`,`order_id`,`batch_msg`,`type`,`ext`,`waitinginstance_id`,`kind`,`parent_id`,`pricemode`,`name`,`makename`,`taste`,`spec_detail_name`,`num`,`account_num`,`unit`,`account_unit`,`price`,`member_price`,`fee`,`ratio`,`ratio_fee`,`ratio_cause`,`status`,`kindmenu_id`,`kindmenu_name`,`menu_id`,`memo`,`is_ratio`,`entity_id`,`is_valid`,`create_time`,`op_time`,`last_ver`,`load_time`,`modify_time`,`draw_status`,`bookmenu_id`,`make_id`,`make_price`,`prodplan_id`,`is_wait`,`specdetail_id`,`specdetail_price`,`makeprice_mode`,`original_price`,`is_buynumber_changed`,`ratio_operator_id`,`child_id`,`kind_bookmenu_id`,`specprice_mode`,`worker_id`,`is_backauth`,`service_fee_mode`,`service_fee`,`orign_id`,`addition_price`,`has_addition`,`seat_id` from `instancedetail`
] jdbcUrl:[jdbc:mysql://192.168.28.200:3306/order2?useUnicode=yes&useCursorFetch=true&useSSL=false&serverTimezone=Asia%2FShanghai&useCompression=true&characterEncoding=utf8&yearIsDateType=false&zeroDateTimeBehavior=convertToNull&tinyInt1isBit=false&rewriteBatchedStatements=true&DataBaseType=true].
2024-04-20 11:43:59 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 0 records, 0 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 0.000s |  All Task WaitReaderTime 0.000s | Percentage 0.00%
2024-04-20 11:44:02 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 0 records, 0 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 0.000s |  All Task WaitReaderTime 0.000s | Percentage 0.00%
2024-04-20 11:44:05 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 0 records, 0 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 0.000s |  All Task WaitReaderTime 0.000s | Percentage 0.00%
2024-04-20 11:44:08 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 76416 records, 20859539 bytes | Speed 6.63MB/s, 25472 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 9.227s |  All Task WaitReaderTime 0.388s | Percentage 0.00%
2024-04-20 11:44:11 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 76416 records, 20859539 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 9.227s |  All Task WaitReaderTime 0.388s | Percentage 0.00%
2024-04-20 11:44:14 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 76416 records, 20859539 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 9.227s |  All Task WaitReaderTime 0.388s | Percentage 0.00%
2024-04-20 11:44:17 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 153536 records, 44858580 bytes | Speed 7.63MB/s, 25706 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 18.403s |  All Task WaitReaderTime 0.773s | Percentage 0.00%
2024-04-20 11:44:20 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 153536 records, 44858580 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 18.403s |  All Task WaitReaderTime 0.773s | Percentage 0.00%
2024-04-20 11:44:23 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 153536 records, 44858580 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 18.403s |  All Task WaitReaderTime 0.773s | Percentage 0.00%
2024-04-20 11:44:26 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 153536 records, 44858580 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 18.403s |  All Task WaitReaderTime 0.773s | Percentage 0.00%
2024-04-20 11:44:29 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 235520 records, 69371796 bytes | Speed 7.79MB/s, 27328 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 27.663s |  All Task WaitReaderTime 1.160s | Percentage 0.00%
2024-04-20 11:44:32 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 235520 records, 69371796 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 27.663s |  All Task WaitReaderTime 1.160s | Percentage 0.00%
2024-04-20 11:44:35 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 235520 records, 69371796 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 27.663s |  All Task WaitReaderTime 1.160s | Percentage 0.00%
2024-04-20 11:44:38 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 314528 records, 92995188 bytes | Speed 7.51MB/s, 26336 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 36.956s |  All Task WaitReaderTime 1.539s | Percentage 0.00%
2024-04-20 11:44:41 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 314528 records, 92995188 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 36.956s |  All Task WaitReaderTime 1.539s | Percentage 0.00%
2024-04-20 11:44:44 INFO mysql_mysql c.a.d.c.s.c.c.j.StandAloneJobContainerCommunicator- Total 314528 records, 92995188 bytes | Speed 0B/s, 0 records/s | Error 0 records, 0 bytes |  All Task WaitWriterTime 36.956s |  All Task WaitReaderTime 1.539s | Percentage 0.00%

猜测执行过程有哪个执行流程block住了，使用 JFR（JAVA FlightRecorder）进行性能分析

java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:FlightRecorderOptions=defaultrecording=true,dumponexit=true,dumponexitpath=/tmp/instancedetail.jfr -Ddata.dir=/tmp/release/tis-uber/data -Denv_props=false -Dlog.dir=/tmp/release/tis-uber/logs -Druntime=daily -Dlogback.configurationFile=logback-datax.xml -DexecTimeStamp=1713576914309 -DnotFetchFromCenterRepository=true -classpath /tmp/release/tis-uber/tis-assemble/lib/*:/tmp/release/tis-uber/data/libs/plugins/tis-datax-local-executor/WEB-INF/lib/*:/tmp/release/tis-uber/tis-assemble/conf:/tmp/release/tis-uber/web-start/lib/* com.qlangtech.tis.datax.DataxExecutor 3 instancedetail_0.json/order2/instancedetail mysql_mysql 127.0.0.1:56432 local -1 ap 1 1713576914309

添加JVM 参数为：

-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:FlightRecorderOptions=defaultrecording=true,dumponexit=true,dumponexitpath=/tmp/instancedetail.jfr