Flirting with parallel programming

[Max mtg]

I have tried to use several threads to accelerate cards load during startup (refers only to reading txt files from cardfolder).

Got following results:
old code (as it was) : ~1600 ms
old code without updating progress bar: ~1050ms
multi-threaded code: ~580 ms. (progress bar is updated when a portion of total files is finished by a thread)

Measured on Core i7-2600/8GB/Win7 x64.

Might also apply similiar code to load decks faster (especially when there are several thousands of decks)


PS: Unfortunatelly I don't know how to divide enumeration coming from zip file into chunks to parse them in a parallel way.

[Sloth]

That loadig speed is insane. Great work Max!

[Chris H.]

Processed 12413 file objects in 1411 ms, apart from that folder scan took 283 ms.

[Max mtg]

Chris, you may compare that time with the one you get with
final int NUMBER_OF_PARTS = 1;
(it's inside forge.card.cardfactory.CardStorageReader.loadAllCardsFromFolder(FProgressBar), it's line about 190)

and only 20 calls to update of progress bar instead of 12k+ is also somewhat faster than before

[Chris H.]

Chris, you may compare that time with the one you get with
final int NUMBER_OF_PARTS = 1;
(it's inside forge.card.cardfactory.CardStorageReader.loadAllCardsFromFolder(FProgressBar), it's line about 190)

 
Processed 12413 file objects in 1476 ms, apart from that folder scan took 233 ms.

[Max mtg]

That's strange... what's your CPU model? Does it have a single core?

My results:
NUMBER_OF_PARTS = 20 ==> Processed 12414 file objects in 450 ms, apart from that folder scan took 117 ms.
NUMBER_OF_PARTS = 16 ==> Processed 12414 file objects in 466 ms, apart from that folder scan took 117 ms.
NUMBER_OF_PARTS = 10 ==> Processed 12414 file objects in 508 ms, apart from that folder scan took 116 ms.
NUMBER_OF_PARTS = 04 ==> Processed 12414 file objects in 493 ms, apart from that folder scan took 119 ms.
NUMBER_OF_PARTS = 02 ==> Processed 12414 file objects in 625 ms, apart from that folder scan took 117 ms.
NUMBER_OF_PARTS = 01 ==> Processed 12414 file objects in 973 ms, apart from that folder scan took 118 ms.

There comes some kind of saturation after 20:
32 parts => Processed 12414 file objects in 483 ms, apart from that folder scan took 120 ms.

Chris, anyway I hope that your ~1400 ms is less than it took before.

[friarsol]

Ouch, that was pretty brutal on first run:

Processed 12412 file objects in 74576 ms, apart from that folder scan took 551 ms.

Second run was only slightly better:

Processed 12412 file objects in 23368 ms, apart from that folder scan took 617 ms.

I'm pretty sure this is a slower load than normally on this machine.

Edit: Third run dropped it down to

Processed 12412 file objects in 3835 ms, apart from that folder scan took 1039 ms.

[Chris H.]

I have a 3.06 GHz Intel Core 2 Duo with two cores.

I am running my test while launching Forge from within Eclipse. Let me try doing a local Maven build and I will then launch from the jar rather than Eclipse.



EDIT:

My test run appeared to be much faster but I can not verify it. I launched forge via the terminal but these was no report like the one that I got with Eclipse:

Code: Select all

CardForge:~ chrish$ /Users/chrish/Desktop/forge-1.3.11-SNAPSHOT\ 2/forge.command ; exit;
Laccolith Rig has no Oracle text.
Paroxysm has no Oracle text.
Read decks: 6 constructed, 0 sealed, 0 draft, 23 cubes, 1 scheme, 1 planar.
Mar 20 19:30:04 CardForge.local java[1623] <Error>: CGContextGetCTM: invalid context 0x0
Mar 20 19:30:04 CardForge.local java[1623] <Error>: CGContextSetBaseCTM: invalid context 0x0
Mar 20 19:30:04 CardForge.local java[1623] <Error>: CGContextGetCTM: invalid context 0x0
Mar 20 19:30:04 CardForge.local java[1623] <Error>: CGContextSetBaseCTM: invalid context 0x0
logout

[Process completed]

[Max mtg]

Sol, the first run is always the longest one - it's the moment when OS reads the very files from disk into its cache.
There are some missing numbers in you post. So did I get your idea correctly that without division of cards array into parts assigned to different threads loading goes much faster for you?


Chris, can you make Forge write the time into forge.log? If I am not mistaken, to achieve that it's enough to use System.err instead of System.out
Also, if you testrun uses a zip file, then it uses the unchanged code.

[Chris H.]

the first run is always the longest one - it's the moment when OS reads the very files from disk into its cache.

 
Turned my computer on this morning and ran forge several times and see that the first run is indeed the longest one:

1] Processed 12413 file objects in 52330 ms, apart from that folder scan took 288 ms.

2] Processed 12413 file objects in 1461 ms, apart from that folder scan took 313 ms.

3] Processed 12413 file objects in 1537 ms, apart from that folder scan took 268 ms.

4] Processed 12413 file objects in 1481 ms, apart from that folder scan took 756 ms.


During the fourth run my Time Machine backup system kicked in and that could explain the slight changes seen.

[Max mtg]

And now when the files are cached - you may experiment with NUMBER_OF_PARTS to see if processing the cards in several threads (that can be run simultaneously on a multi-core CPU) gives any advantage.

My original intention was to decrease loading time by reducing number of progress bar updates and using threads.

[friarsol]

Sol, the first run is always the longest one - it's the moment when OS reads the very files from disk into its cache.
There are some missing numbers in you post. So did I get your idea correctly that without division of cards array into parts assigned to different threads loading goes much faster for you?

It seems like the first time was much longer than it used to be, and the second time is worse than the second time used to be. After that it seems generally better. Maybe 20 parts is just too many parts for a single core PC.

[Max mtg]

Looks like I'll have to add a code path to perform this action without a thread pool, that is to iterate over parts sequentally in the same thread.

I am planning to apply the same method in StorageReaders (I don't remember exact name) that read deck collections and other objects.

That's going to serve as an introduction to concurrent programming for me

[Max mtg]

Maybe 20 parts is just too many parts for a single core PC.

Not at all, a thread pool takes number of logical cores of your processor into consideration when it is created.
All parts are queued and executed by the first avaliable thread, when it's idle or is finished with previous part.

So I expect just 2 threads to be created on a single-core PC.

[Chris H.]

A few more runs:


NUMBER_OF_PARTS

= 1] Processed 12413 file objects in 2458 ms, apart from that folder scan took 287 ms.

= 2] Processed 12413 file objects in 1284 ms, apart from that folder scan took 226 ms.

= 3] Processed 12413 file objects in 1286 ms, apart from that folder scan took 272 ms.

= 4] Processed 12413 file objects in 1391 ms, apart from that folder scan took 234 ms.

= 5] Processed 12413 file objects in 1287 ms, apart from that folder scan took 287 ms.

= 10] Processed 12413 file objects in 1407 ms, apart from that folder scan took 289 ms.

= 20] Processed 12413 file objects in 1537 ms, apart from that folder scan took 224 ms.

= 30] Processed 12413 file objects in 1483 ms, apart from that folder scan took 223 ms.

= 50] Processed 12413 file objects in 1444 ms, apart from that folder scan took 290 ms.