QA » openQA Project

https://github.com/os-autoinst/openQA/pull/3515 to fix the current timeout I observe in local environment

And I ran the test module locally recording the relative times:

$ unbuffer prove -l -v  --timer t/25-cache.t 2>&1 | ts -i '%H:%M:%.S' | ts -s '%H:%M:%.S'
00:00:01.755069 00:00:01.748350 [17:19:46] t/25-cache.t .. 
00:00:01.755139 00:00:00.000088 ok 1 - version 2 is the latest version
00:00:01.755311 00:00:00.000237 ok 2 - version 2 is the active version
00:00:01.755541 00:00:00.000229 ok 3 - Cache directory tree created
00:00:01.755740 00:00:00.000204 ok 4 - Cache limit is default (50GB)
00:00:01.755888 00:00:00.000149 ok 5 - cache.sqlite is present
00:00:01.758904 00:00:00.002994 ok 6 - version 2 is still the active version
00:00:01.759080 00:00:00.000173 ok 7 - Cache limit/size match the expected 100GB/168)
00:00:01.759280 00:00:00.000215 ok 8 - Registered assets 1 and 3 were kept
00:00:01.759501 00:00:00.000210 ok 9 - Asset 2 was removed
00:00:01.761862 00:00:00.002315 ok 10 - Cache limit/size match the expected 100/84)
00:00:01.761898 00:00:00.000077 ok 11 - Requested size is logged
00:00:01.762060 00:00:00.000180 ok 12 - Oldest asset (1.qcow2) removal was logged
00:00:01.762186 00:00:00.000130 ok 13 - Oldest asset (1.qcow2) was sucessfully removed
00:00:05.774349 00:00:04.012134 ok 14 - Asset download attempt
00:00:05.774387 00:00:00.000052 ok 15 - Asset download fails with: 521 Connection refused
00:00:05.778701 00:00:00.004305 # Waiting for cache service to become available
00:00:05.890208 00:00:00.111459 ok 16 - Asset download attempt
00:00:05.890328 00:00:00.000169 ok 17 - Asset download fails with: 404 Not Found
00:00:05.894324 00:00:00.003993 ok 18 - Asset download attempt
00:00:05.894430 00:00:00.000117 ok 19 - Asset download fails with 400 Bad Request
00:00:09.911081 00:00:04.016630 ok 20 - Asset download attempt
00:00:09.911227 00:00:00.000154 ok 21 - Real error is logged
00:00:09.911294 00:00:00.000101 ok 22 - 4 tries remaining
00:00:09.911429 00:00:00.000136 ok 23 - 3 tries remaining
00:00:09.911617 00:00:00.000189 ok 24 - 2 tries remaining
00:00:09.911808 00:00:00.000170 ok 25 - 1 tries remaining
00:00:09.914732 00:00:00.002897 ok 26 - Bailing out after too many retries
00:00:09.915304 00:00:00.000591 ok 27 - Asset does not exist in cache
00:00:09.917223 00:00:00.001919 ok 28 - Asset download attempt
00:00:09.917376 00:00:00.000164 ok 29 - Real error is logged
00:00:09.917470 00:00:00.000107 ok 30 - No retries
00:00:09.917581 00:00:00.000112 ok 31 - Asset does not exist in cache
00:00:38.943630 00:00:29.026011 ok 32 - Asset download attempt
00:00:38.943824 00:00:00.000195 ok 33 - Incomplete download logged
00:00:38.943862 00:00:00.000019 ok 34 - 4 tries remaining
00:00:38.943996 00:00:00.000187 ok 35 - 3 tries remaining
00:00:38.944100 00:00:00.000108 ok 36 - 2 tries remaining
00:00:38.944204 00:00:00.000104 ok 37 - 1 tries remaining
00:00:38.944342 00:00:00.000138 ok 38 - Bailing out after too many retries
00:00:38.944453 00:00:00.000112 ok 39 - Asset does not exist in cache
00:00:42.969024 00:00:04.024533 ok 40 - Asset download attempt
00:00:42.969082 00:00:00.000086 ok 41 - Real error is logged
00:00:42.969348 00:00:00.000231 ok 42 - 4 tries remaining
00:00:42.969550 00:00:00.000232 ok 43 - 3 tries remaining
00:00:42.969745 00:00:00.000194 ok 44 - 2 tries remaining
00:00:42.969887 00:00:00.000154 ok 45 - 1 tries remaining
00:00:42.970084 00:00:00.000199 ok 46 - Bailing out after too many retries
00:00:42.970271 00:00:00.000189 ok 47 - Asset was missing
00:00:42.970462 00:00:00.000176 ok 48 - Asset does not exist in cache
00:00:46.988704 00:00:04.018209 ok 49 - Asset download attempt
00:00:46.988756 00:00:00.000084 ok 50 - Asset download fails with 503 - Server not available
00:00:46.988896 00:00:00.000147 ok 51 - 4 tries remaining
00:00:46.989216 00:00:00.000316 ok 52 - Bailing out after too many retries
00:00:46.989245 00:00:00.000035 ok 53 - Asset does not exist in cache
00:00:46.996839 00:00:00.007568 ok 54 - Asset download attempt
00:00:46.996984 00:00:00.000158 ok 55 - Full download logged
00:00:46.997146 00:00:00.000169 ok 56 - Etag and size are logged
00:00:46.997232 00:00:00.000087 ok 57 - Asset exist in cache
00:00:47.001682 00:00:00.004424 ok 58 - Asset download attempt
00:00:47.001763 00:00:00.000104 ok 59 - Content has not changed
00:00:47.005903 00:00:00.004113 ok 60 - Asset download attempt
00:00:47.005941 00:00:00.000066 ok 61 - Content has not changed
00:00:47.013513 00:00:00.007551 ok 62 - Asset download attempt
00:00:47.014029 00:00:00.000524 ok 63 - Full download logged
00:00:47.014181 00:00:00.000163 ok 64 - Etag and size are logged
00:00:47.014338 00:00:00.000166 ok 65 - Requested size is logged
00:00:47.014496 00:00:00.000162 ok 66 - Reclaimed space for new smaller asset
00:00:47.020384 00:00:00.005859 ok 67 - Asset with special characters was downloaded successfully
00:00:47.020513 00:00:00.000145 ok 68 - Etag and size are logged
00:00:47.028500 00:00:00.007965 ok 69 - Asset download attempt
00:00:47.028680 00:00:00.000195 ok 70 - Full download logged
00:00:47.028846 00:00:00.000188 ok 71 - Etag and size are logged
00:00:47.033686 00:00:00.004809 ok 72 - Asset download attempt
00:00:47.033855 00:00:00.000142 ok 73 - Content has not changed
00:00:47.034019 00:00:00.000218 # Subtest: track assets
00:00:47.035039 00:00:00.001014     ok 1 - Asset is there
00:00:47.036680 00:00:00.001630     ok 2 - Asset was purged since was not tracked
00:00:47.036892 00:00:00.000180     ok 3 - Asset is there
00:00:47.037373 00:00:00.000496     ok 4 - Asset was purged
00:00:47.038248 00:00:00.000892     ok 5 - Asset was just inserted, so it must be there
00:00:47.038799 00:00:00.000557     ok 6 - Can get downloading state with _asset()
00:00:47.039425 00:00:00.000594     ok 7 - asset() returns {} if asset is not present
00:00:47.039891 00:00:00.000472     1..7
00:00:47.040300 00:00:00.000410 ok 74 - track assets
00:00:47.040455 00:00:00.000184 # Subtest: cache directory is symlink
00:00:47.043145 00:00:00.002684     ok 1 - symlinking cache dir to /tmp/quaWHJZBVi/t/cache.d/symlink
00:00:47.049143 00:00:00.005981     ok 2 - Asset download attempt
00:00:47.049212 00:00:00.000096     ok 3 - Full download logged
00:00:47.049281 00:00:00.000065     ok 4 - Etag and size are logged
00:00:47.054799 00:00:00.005473     ok 5 - Asset download attempt
00:00:47.054930 00:00:00.000176     ok 6 - Content has not changed
00:00:47.056271 00:00:00.001339     ok 7 - Cache limit/size match the expected 1024/1024)
00:00:47.058974 00:00:00.002701     ok 8 - Reclaimed 1024 Byte
00:00:47.059219 00:00:00.000248     ok 9 - Cache limit is 512 Byte
00:00:47.059617 00:00:00.000403     1..9
00:00:47.059978 00:00:00.000366 ok 75 - cache directory is symlink
00:00:47.060188 00:00:00.000201 # Subtest: cache tmp directory is used for downloads
00:00:47.069031 00:00:00.008825     ok 1 - cache tmp directory was used
00:00:47.069088 00:00:00.000080     1..1
00:00:47.069248 00:00:00.000154 ok 76 - cache tmp directory is used for downloads
00:00:48.075846 00:00:01.006576 ok 77 - no (unexpected) warnings (via done_testing)
00:00:48.076033 00:00:00.000201 1..77
00:00:48.130289 00:00:00.054213 ok    48021 ms ( 0.02 usr  0.00 sys +  1.75 cusr  0.17 csys =  1.94 CPU)
00:00:48.130577 00:00:00.000317 [17:20:34]
00:00:48.130621 00:00:00.000032 All tests successful.
00:00:48.130646 00:00:00.000013 Files=1, Tests=77, 48 wallclock secs ( 0.04 usr  0.00 sys +  1.75 cusr  0.17 csys =  1.96 CPU)
00:00:48.130669 00:00:00.000010 Result: PASS

By far the biggest contributor in runtime is:

00:00:09.917581 00:00:00.000112 ok 31 - Asset does not exist in cache
00:00:38.943630 00:00:29.026011 ok 32 - Asset download attempt

Wow, you have a fix already. That's great!

kraih did an awesome improvement, merged. I closed my PR. Thanks!