Slow saving?

[metavibor]

I trying to save the binned and chromatically corrected data as "Tiff Volumes" (no compression, no 8bit conversion). When I do this in BDP2 it takes approximately 5-10x longer than when I do it from the BDP (applying the same corrections and saving with (what appears to me) same settings, same no. of I/O threads). For example, the described correction and saving process took 5min for 100GB dataset when doing it from BDP compared to cca. 50min using BDP2.

[tischi]

Yeah....I did expect that the BDP2 is slower, because of how things are done internally, but I did not expect that it is that much. I will check whether I can speed things up. This is not a simple thing though...

Would you still use it? I guess the argument could be that once one configured all the processing steps one could just let it run over night. In other words, do you think saving speed is a critical issue?

[tischi]

Could you do me a favour and try whether this speed difference is specific to the binning? In other words, if you only do the chromatic shift correction, is it as much difference?

[metavibor]

Without the binning BDP is still cca. 3x faster than BDP2 sure the speed is not so critical when doing things over night on TB size data (although the speed difference is significant so it might affect those data volumes as well). In our case we have 100-200GB size data which we processed in BDP (chromatic shift, binning, saving as tiff) and than analysed in Imaris. The entire workflow in BDP including the saving took only cca. 5min (we new the exact amount of binning and the chromatic correction because we looked at the same data using the "interactivity" of BDP2 just before). So it was very satisfying when we could work on the data in Imaris after only 5min. Compared with a gap of 30-40min that was needed for saving when using BDP2. You see what I mean - 5min one can wait and continue with the analysis, but what do you do for 30-40min? After 40 min I'm already doing another project and I forgot what I was doing there in the first place :) ...it is different when something takes 2h vs 6h, I would run both things over night and than I would not care about the speed difference but when I can choose between 5 min and 30 min than I go with 5.

[tischi]

makes sense! I will see what I can do!

[tischi]

Hi @metavibor,

1. Your workflow is saving from Luxendo h5 files to Imaris, correct?
2. If so, could you please try again, I worked on it, and changed some things, hopefully it is faster now.
3. Could you also please check how setting the number of IO threads during saving to one compares with having more threads (the hdf5 library is inherently single threaded, so it is in fact not so clear whether multi-threading helps...)?
4. Could you please paste here the text from the log window from the trial with one thread?

Thanks a lot for the testing!

[metavibor]

Hi @tischi, Here are some answers:

1. Your workflow is saving from Luxendo h5 files to Imaris, correct? yes

2. If so, could you please try again, I worked on it, and changed some things, hopefully it is faster now. It is much faster now. BDP is still somewhat faster (needs 3min for the task vs 4min that BDP2 needs at I/O=5) but this does not matter. So - great!! Thank you!

3. Could you also please check how setting the number of IO threads during saving to one compares with having more threads (the hdf5 library is inherently single threaded, so it is in fact not so clear whether multi-threading helps...)? The whole process scales nicely linearly with the number of I/O (my workstation has 10 cores (and 20 logical processors)). I/O=1 -> 20min for the task I/O=5 -> 4min for the task I/O=10 -> 2min for the task I/O=20 -> a bit less than 2min (runs the CPU at almost 100% (compared to cca 60-70% at I/O=10) but for some reason that did not translate into faster job execution... I could not see any obvious bottlenecks in the hardware. I was saving on the SSD... it does not matter, just a curiosity) I decided to use I/O=10

4. Could you please paste here the text from the log window from the trial with one thread? Here is the content of the log window with one thread trial:

"Searching files in folder: Z:\Data\SPIM_tests\Samy\190314\dense collagen\2019-03-14_14.30.33\stack_1_channel_0\ Number of files in main folder matching the filter pattern: 60 Folder: Z:\Data\SPIM_tests\Samy\190314\dense collagen\2019-03-14_14.30.33\stack_1_channel_0\ FileType: Hdf5 BitDepth: 16 nX: 2048 nY: 2048 nZ: 181 nC: 2 nT: 30 GB: 91.10028288

Image size without binning [GB]: 91.10028288 Binned view size [GB]: 30.38158848 Binned view size [GB]: 10.13214108 Saving: Started... Saving: Configuring volume-wise reader...

Saved file: 1/60; time ( spent, left, task ) [ s ]: 17, 1054, 17; memory: 2054MB of 97951MB (2%)

Saved file: 2/60; time ( spent, left, task ) [ s ]: 34, 1013, 17; memory: 3507MB of 97951MB (3%)

Saved file: 3/60; time ( spent, left, task ) [ s ]: 52, 997, 17; memory: 4942MB of 97951MB (5%)

Saved file: 4/60; time ( spent, left, task ) [ s ]: 69, 974, 17; memory: 6392MB of 97951MB (6%)

Saved file: 5/60; time ( spent, left, task ) [ s ]: 87, 960, 17; memory: 7832MB of 97951MB (7%)

Saved file: 6/60; time ( spent, left, task ) [ s ]: 105, 945, 17; memory: 9290MB of 97951MB (9%)

Saved file: 7/60; time ( spent, left, task ) [ s ]: 122, 929, 17; memory: 10726MB of 97951MB (10%)

Saved file: 8/60; time ( spent, left, task ) [ s ]: 140, 911, 17; memory: 12175MB of 97951MB (12%)

Saved file: 9/60; time ( spent, left, task ) [ s ]: 158, 897, 17; memory: 13631MB of 97951MB (13%)

Saved file: 10/60; time ( spent, left, task ) [ s ]: 176, 882, 17; memory: 15079MB of 97951MB (15%)

Saved file: 11/60; time ( spent, left, task ) [ min ]: 3, 14, 0; memory: 16519MB of 97951MB (16%)

Saved file: 12/60; time ( spent, left, task ) [ min ]: 3, 14, 0; memory: 17967MB of 97951MB (18%)

Saved file: 13/60; time ( spent, left, task ) [ min ]: 3, 13, 0; memory: 19415MB of 97951MB (19%)

Saved file: 14/60; time ( spent, left, task ) [ min ]: 4, 13, 0; memory: 20864MB of 97951MB (21%)

Saved file: 15/60; time ( spent, left, task ) [ min ]: 4, 13, 0; memory: 22315MB of 97951MB (22%)

Saved file: 16/60; time ( spent, left, task ) [ min ]: 4, 12, 0; memory: 23760MB of 97951MB (24%)

Saved file: 17/60; time ( spent, left, task ) [ min ]: 5, 12, 0; memory: 25217MB of 97951MB (25%)

Saved file: 18/60; time ( spent, left, task ) [ min ]: 5, 12, 0; memory: 26665MB of 97951MB (27%)

Saved file: 19/60; time ( spent, left, task ) [ min ]: 5, 12, 0; memory: 28114MB of 97951MB (28%)

Saved file: 20/60; time ( spent, left, task ) [ min ]: 5, 11, 0; memory: 29551MB of 97951MB (30%)

Saved file: 21/60; time ( spent, left, task ) [ min ]: 6, 11, 0; memory: 30999MB of 97951MB (31%)

Saved file: 22/60; time ( spent, left, task ) [ min ]: 6, 11, 0; memory: 32447MB of 97951MB (33%)

Saved file: 23/60; time ( spent, left, task ) [ min ]: 6, 11, 0; memory: 33895MB of 97951MB (34%)

Saved file: 24/60; time ( spent, left, task ) [ min ]: 7, 10, 0; memory: 35343MB of 97951MB (36%)

Saved file: 25/60; time ( spent, left, task ) [ min ]: 7, 10, 0; memory: 36791MB of 97951MB (37%)

Saved file: 26/60; time ( spent, left, task ) [ min ]: 7, 10, 0; memory: 38239MB of 97951MB (39%)

Saved file: 27/60; time ( spent, left, task ) [ min ]: 8, 9, 0; memory: 39688MB of 97951MB (40%)

Saved file: 28/60; time ( spent, left, task ) [ min ]: 8, 9, 0; memory: 41136MB of 97951MB (41%)

Saved file: 29/60; time ( spent, left, task ) [ min ]: 8, 9, 0; memory: 42595MB of 97951MB (43%)

Saved file: 30/60; time ( spent, left, task ) [ min ]: 8, 8, 0; memory: 44032MB of 97951MB (44%)

Saved file: 31/60; time ( spent, left, task ) [ min ]: 9, 8, 0; memory: 45480MB of 97951MB (46%)

Saved file: 32/60; time ( spent, left, task ) [ min ]: 9, 8, 0; memory: 46928MB of 97951MB (47%)

Saved file: 33/60; time ( spent, left, task ) [ min ]: 9, 8, 0; memory: 48376MB of 97951MB (49%)

Saved file: 34/60; time ( spent, left, task ) [ min ]: 10, 7, 0; memory: 49824MB of 97951MB (50%)

Saved file: 35/60; time ( spent, left, task ) [ min ]: 10, 7, 0; memory: 51272MB of 97951MB (52%)

Saved file: 36/60; time ( spent, left, task ) [ min ]: 10, 7, 0; memory: 52720MB of 97951MB (53%)

Saved file: 37/60; time ( spent, left, task ) [ min ]: 11, 6, 0; memory: 54168MB of 97951MB (55%)

Saved file: 38/60; time ( spent, left, task ) [ min ]: 11, 6, 0; memory: 55616MB of 97951MB (56%)

Saved file: 39/60; time ( spent, left, task ) [ min ]: 11, 6, 0; memory: 57065MB of 97951MB (58%)

Saved file: 40/60; time ( spent, left, task ) [ min ]: 12, 6, 0; memory: 58513MB of 97951MB (59%)

Saved file: 41/60; time ( spent, left, task ) [ min ]: 12, 5, 0; memory: 59962MB of 97951MB (61%)

Saved file: 42/60; time ( spent, left, task ) [ min ]: 12, 5, 0; memory: 61409MB of 97951MB (62%)

Saved file: 43/60; time ( spent, left, task ) [ min ]: 12, 5, 0; memory: 62857MB of 97951MB (64%)

Saved file: 44/60; time ( spent, left, task ) [ min ]: 13, 4, 0; memory: 64305MB of 97951MB (65%)

Saved file: 45/60; time ( spent, left, task ) [ min ]: 13, 4, 0; memory: 65753MB of 97951MB (67%)

Saved file: 46/60; time ( spent, left, task ) [ min ]: 13, 4, 0; memory: 67201MB of 97951MB (68%)

Saved file: 47/60; time ( spent, left, task ) [ min ]: 14, 3, 0; memory: 68650MB of 97951MB (70%)

Saved file: 48/60; time ( spent, left, task ) [ min ]: 14, 3, 0; memory: 70097MB of 97951MB (71%)

Saved file: 49/60; time ( spent, left, task ) [ min ]: 14, 3, 0; memory: 71546MB of 97951MB (73%)

Saved file: 50/60; time ( spent, left, task ) [ min ]: 15, 3, 0; memory: 72994MB of 97951MB (74%)

Saved file: 51/60; time ( spent, left, task ) [ min ]: 15, 2, 0; memory: 74442MB of 97951MB (75%)

Saved file: 52/60; time ( spent, left, task ) [ min ]: 15, 2, 0; memory: 75890MB of 97951MB (77%)

Saved file: 53/60; time ( spent, left, task ) [ min ]: 16, 2, 0; memory: 77338MB of 97951MB (78%)

Saved file: 54/60; time ( spent, left, task ) [ min ]: 16, 1, 0; memory: 78786MB of 97951MB (80%)

Saved file: 55/60; time ( spent, left, task ) [ min ]: 16, 1, 0; memory: 80234MB of 97951MB (81%)

Saved file: 56/60; time ( spent, left, task ) [ min ]: 16, 1, 0; memory: 81682MB of 97951MB (83%)

Saved file: 57/60; time ( spent, left, task ) [ min ]: 17, 0, 0; memory: 83130MB of 97951MB (84%)

Saved file: 58/60; time ( spent, left, task ) [ min ]: 17, 0, 0; memory: 84578MB of 97951MB (86%)

Saved file: 59/60; time ( spent, left, task ) [ min ]: 17, 0, 0; memory: 86026MB of 97951MB (87%)

Saved file: 60/60; time ( spent, left, task ) [ min ]: 18, 0, 0; memory: 87474MB of 97951MB (89%)"

[metavibor]

just a correction on question 1. I'm saving from Luxendo h5 to "tiff volumes"

[tischi]

Great! Happy to hear that it improved that much!!

1. Could you please update your Fiji and test it again. Maybe it is even faster now.... You will be able to play with IO threads and processing threads separately.
2. Why do you save as Tiff and not directly as Imaris?

[metavibor]

1. will do. If you could do for the "Bin" function the same thing you did for the "ChromaticShiftCorrection" that would be great (#54 in case you forgot)
2. I didn't see the benefit of saving in Imaris format since Imaris can open tiff volumes nicely. I'm not familiar with the Imaris format and I thought with tiffs I'm more flexible if I need to go to another software at some point. What is the benefit of saving directly in Imaris format?

[tischi]

Imaris will forbid soon to open Tiff, because the performance of Imaris is not good when working on Tiff based format.