Question of ParallelJob Example Execution

[balakriz]

Hello Experts,

I was quite impressed by the parallel job example and tried out the same example with MySQL as the db. I found that the time taken for execution is more than 110 ms. (Please note that I didn't do any change in the code, except for the value in data-source-context.xml) However, with default configuration (hsql) it takes just 30 ms to execute all the processes.

A quick look at the console output showed that the processes were getting executed sequentially and not parallely when MySQL was used. Please find below the console output and correct me in case I am wrong.

I tried executing it 20 times atleast and the results are same. Kindly help me in understanding the reason behind the same. (From the console output, I was also able to notice that the properties like 'Default batch size' etc., are all same in both the dbs).

Is it a db specific issue?

With HSQL

18:56:46,500 DEBUG SimpleAsyncTaskExecutor-1 StagingItemReader:140 - Retrieved key from list: 0
18:56:46,500 DEBUG SimpleAsyncTaskExecutor-2 StagingItemReader:140 - Retrieved key from list: 1
18:56:46,500 DEBUG SimpleAsyncTaskExecutor-4 StagingItemReader:140 - Retrieved key from list: 2
18:56:46,500 DEBUG SimpleAsyncTaskExecutor-3 StagingItemReader:140 - Retrieved key from list: 3
18:56:46,500 DEBUG SimpleAsyncTaskExecutor-4 TradeWriter:50 - Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:56:46,500 DEBUG SimpleAsyncTaskExecutor-3 TradeWriter:50 - Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-2 TradeWriter:50 - Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-1 TradeWriter:50 - Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-4 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-3 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-2 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:56:46,515  INFO SimpleAsyncTaskExecutor-4 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:56:46,515  INFO SimpleAsyncTaskExecutor-3 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-1 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:56:46,515  INFO SimpleAsyncTaskExecutor-2 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:56:46,515  INFO SimpleAsyncTaskExecutor-1 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-3 StagingItemReader:184 - Clearing buffer on commit: [3]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-5 StagingItemReader:140 - Retrieved key from list: 4
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-4 StagingItemReader:184 - Clearing buffer on commit: [2]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-2 StagingItemReader:184 - Clearing buffer on commit: [1]
18:56:46,515 DEBUG SimpleAsyncTaskExecutor-1 StagingItemReader:184 - Clearing buffer on commit: [0]
18:56:46,531 DEBUG SimpleAsyncTaskExecutor-5 TradeWriter:50 - Trade: [isin=UK21341EAH45,quantity=215,price=35.11,customer=customer5]
18:56:46,531 DEBUG SimpleAsyncTaskExecutor-5 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH45,quantity=215,price=35.11,customer=customer5]

With MySQL

18:53:11,234 DEBUG SimpleAsyncTaskExecutor-2 StagingItemReader:140 - Retrieved key from list: 1
18:53:11,234 DEBUG SimpleAsyncTaskExecutor-2 TradeWriter:50 - Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:53:11,250 DEBUG SimpleAsyncTaskExecutor-2 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:53:11,250  INFO SimpleAsyncTaskExecutor-2 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH41,quantity=211,price=31.11,customer=customeb1]
18:53:11,250 DEBUG SimpleAsyncTaskExecutor-2 StagingItemReader:184 - Clearing buffer on commit: [1]
18:53:11,250 DEBUG SimpleAsyncTaskExecutor-4 StagingItemReader:140 - Retrieved key from list: 2
18:53:11,265 DEBUG SimpleAsyncTaskExecutor-4 TradeWriter:50 - Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:53:11,265 DEBUG SimpleAsyncTaskExecutor-4 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:53:11,265  INFO SimpleAsyncTaskExecutor-4 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH42,quantity=212,price=32.11,customer=customer2]
18:53:11,281 DEBUG SimpleAsyncTaskExecutor-1 StagingItemReader:140 - Retrieved key from list: 3
18:53:11,281 DEBUG SimpleAsyncTaskExecutor-1 TradeWriter:50 - Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:53:11,296 DEBUG SimpleAsyncTaskExecutor-1 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:53:11,296  INFO SimpleAsyncTaskExecutor-1 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH43,quantity=213,price=33.11,customer=customer3]
18:53:11,312 DEBUG SimpleAsyncTaskExecutor-3 StagingItemReader:140 - Retrieved key from list: 4
18:53:11,312 DEBUG SimpleAsyncTaskExecutor-3 TradeWriter:50 - Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:53:11,312 DEBUG SimpleAsyncTaskExecutor-3 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:53:11,312  INFO SimpleAsyncTaskExecutor-3 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH44,quantity=214,price=34.11,customer=customer4]
18:53:11,328 DEBUG SimpleAsyncTaskExecutor-5 StagingItemReader:140 - Retrieved key from list: 5
18:53:11,328 DEBUG SimpleAsyncTaskExecutor-4 StagingItemReader:184 - Clearing buffer on commit: [2]
18:53:11,328 DEBUG SimpleAsyncTaskExecutor-5 TradeWriter:50 - Trade: [isin=UK21341EAH45,quantity=215,price=35.11,customer=customer5]
18:53:11,328 DEBUG SimpleAsyncTaskExecutor-5 JdbcTradeDao:53 - Processing: Trade: [isin=UK21341EAH45,quantity=215,price=35.11,customer=customer5]
18:53:11,343  INFO SimpleAsyncTaskExecutor-5 ProcessorLogAdvice:53 - Processed: Trade: [isin=UK21341EAH45,quantity=215,price=35.11,customer=customer5]

Thanks,
Kriz.

[lucasward]

It's likely an issue with the transaction isolation level. In the latest 1.1 trunk you can set this for the business transaction (i.e. the transaction controlled by the step). However, in 1.0.1 you could override the default in the datasource itself.

[balakriz]

Hello Lucas,

Thanks for the prompt response. It does execute two threads parallely (but not all), when the transaction isolation level is set to any of the Isolation enum values other than SERIALIZABLE. What else could be the hindering factor?

Best regards,
Bala