Wrong time estimation

[Phhere]

Hello, when running dsync from 0.11 release we get wrong time estimations and percentage for create step.

[2021-08-10T09:18:43] Walking source path [2021-08-10T09:18:43] Walking /gpfs/project/bmfz_hiseq/hiseq3000/190118_J00150_0043_AHYJY5BBXX [2021-08-10T09:18:53] Walked 379796 items in 10.006 secs (37955.192 items/sec) ... [2021-08-10T09:19:03] Walked 750285 items in 20.008 secs (37498.654 items/sec) ... [2021-08-10T09:19:10] Walked 1036966 items in 27.748 secs (37370.283 items/sec) ... [2021-08-10T09:19:10] Walked 1036966 items in 27.752 seconds (37365.127 items/sec) [2021-08-10T09:19:10] Walking destination path [2021-08-10T09:19:10] Walking /gpfs/project/projects/bmfz_gtl/devices/illumina/hiseq3000/190118_J00150_0043_AHYJY5BBXX [2021-08-10T09:19:20] Walked 389119 items in 10.016 secs (38848.717 items/sec) ... [2021-08-10T09:19:21] Walked 408773 items in 10.719 secs (38133.718 items/sec) ... [2021-08-10T09:19:21] Walked 408773 items in 10.721 seconds (38126.757 items/sec) [2021-08-10T09:19:22] Comparing file sizes and modification times of 55 items [2021-08-10T09:19:22] Started : Aug-10-2021, 09:19:21 [2021-08-10T09:19:22] Completed : Aug-10-2021, 09:19:22 [2021-08-10T09:19:22] Seconds : 0.250 [2021-08-10T09:19:22] Items : 55 [2021-08-10T09:19:22] Item Rate : 55 items in 0.250470 seconds (219.586775 items/sec) [2021-08-10T09:19:22] Deleting items from destination [2021-08-10T09:19:22] Removing 404544 items [2021-08-10T09:19:32] Removed 103598 items (25.61%) in 10.093 secs (10264.599 items/sec) 29 secs remaining ... [2021-08-10T09:19:42] Removed 239696 items (59.25%) in 20.073 secs (11941.366 items/sec) 13 secs remaining ... [2021-08-10T09:19:52] Removed 361805 items (89.44%) in 30.058 secs (12036.728 items/sec) 3 secs remaining ... [2021-08-10T09:20:00] Removed 404544 items (100.00%) in 38.627 secs (10473.017 items/sec) done [2021-08-10T09:20:00] Removed 404544 items in 38.638 seconds (10470.224 items/sec) [2021-08-10T09:20:00] Copying items to destination [2021-08-10T09:20:00] Copying to /gpfs/project/projects/bmfz_gtl/devices/illumina/hiseq3000/190118_J00150_0043_AHYJY5BBXX [2021-08-10T09:20:00] Items: 1032737 [2021-08-10T09:20:00] Directories: 0 [2021-08-10T09:20:00] Files: 1032737 [2021-08-10T09:20:00] Links: 0 [2021-08-10T09:20:00] Data: 884.521 GiB (898.086 KiB per file) [2021-08-10T09:20:00] Creating 1032737 files. [2021-08-10T09:20:10] Created 123890 items (0%) in 10.025 secs (12358.628 items/sec) 1492620759615424 secs left ... [2021-08-10T09:20:20] Created 277396 items (0%) in 20.036 secs (13844.686 items/sec) 1332406134277198 secs left ... [2021-08-10T09:20:30] Created 426615 items (0%) in 30.056 secs (14194.013 items/sec) 1299614387964282 secs left ... [2021-08-10T09:20:40] Created 560112 items (0%) in 40.065 secs (13980.236 items/sec) 1319487274576821 secs left ... [2021-08-10T09:21:13] Created 665770 items (0%) in 73.161 secs (9100.020 items/sec) 2027110377897685 secs left ... [2021-08-10T09:21:23] Created 836500 items (0%) in 83.116 secs (10064.229 items/sec) 1832901907468153 secs left ... [2021-08-10T09:21:33] Created 924931 items (0%) in 93.104 secs (9934.364 items/sec) 1856862132215938 secs left ... [2021-08-10T09:21:37] Created 1018082 items (0%) in 96.540 secs (10545.722 items/sec) 1749215772089348 secs left ... [2021-08-10T09:21:37] Created 1032737 items (0%) in 96.540 secs (10697.493 items/sec) done

I think the issue must be somewhere in https://github.com/hpc/mpifileutils/blob/55255604d87d581eb52a710c2accad31581136e7/src/common/mfu_flist_create.c#L172

[adammoody]

Wow, that would certainly take a long time to finish!

Thanks for the report @Phhere . I'll take a look.

[adammoody]

@Phhere , thank you again for reporting this. I was able to reproduce the problem and verified that PR https://github.com/hpc/mpifileutils/pull/497 fixed the bug.

We hope to tag a new v0.11.1 around late Sept or early Oct which will include this fix.

@dsikich , thank you as well for noting this.