Performance regression in nccopy for large 64-bit offset files

Hi

A user at our site has reported that the following operation on certain 64-bit offset files created by their model has seen an increase in runtime by a factor of over 100 between netcdf/4.7.3 and netcdf/4.7.4.
nccopy -d 5 -s <infile> <outfile>
We run CentOS 8.1, and have reproduced this issue with both GCC 8.3 and Intel 2019.5 compilers. In all cases, NetCDF has been built against HDF5 1.10.5, HDF4 4.2.14 and szip 2.1. We're using autotools with the following configure options:
--enable-hdf4 --enable-mmap --disable-dap-remote-tests
I've narrowed this down to the case where is a 64-bit offset file over approx. 4GB in size. Files under this size, or in other formats don't appear to be affected. I've been using the following steps to reproduce:

wget http://dapds00.nci.org.au/thredds/fileServer/fx3/gbr4/gbr4_simple_2016-06.nc
ncks --64bit_offset gbr4_simple_2016-06.nc gbr4_simple_2016-06.nc.64
nccopy -d 5 -s gbr4_simple_2016-06.nc.64 gbr4_simple_2016-06.nc.474

This downloads a 4.5GB compressed classic model file and deflates it to a 13.8GB 64-bit offset file. When run using nccopy provided by NetCDF 4.7.3, the operation takes around 260 seconds on our system. When run using nccopy provided by NetCDF 4.7.4, the same operation takes around 32,000 seconds. I've tried setting identical chunk parameters between the two versions as described in #1757, but this did not improve performance. This regression also appears at different deflation levels (including 0, though that only takes twice as long), though I've been focused on the -d 5 case.
I've gathered some profiling data, and strace output, and from what I can tell, its taking a very different pathway inside HDF5. Both cases appear to follow the same pathway to H5D__chunk_write. Then, in the 4.7.3 case, the majority of the writes are occurring inside the H5D__chunk_cache_prune function, but in the 4.7.4 case, the writes are occurring H5D__chunk_unlock. Furthermore, nccopy 4.7.4 reading large amounts of data from the output file (during H5D__chunk_lock), then writing a significant amount more data that nccopy 4.7.3. Strace shows nccopy 4.7.4. Below is a snippet from strace -epwrite64,pread64 nccopy -d 5 -s gbr4_simple_2016-06.nc.64 gbr4_simple_2016-06.nc.474

pread64(5, "x^\354\335uXU\353\2727~:\247\204\200( \335\215H\227\nH\2034H7HJ\203Hw"..., 686159840, 603883237) = 686159840
pwrite64(5, "x^\354\335uXU\353\2727~:\247\204\200( \335\215H\227\nH\2034H7HJ\203Hw"..., 692154506, 40796584) = 692154506
pread64(5, "x^\354\335uXT\373\3727~)\1\31ZiP:\245\273K\220n\245\33\244SB\244\273\21\1"..., 909870723, 1290043077) = 909870723
pwrite64(5, "x^\354\335uXT\373\3727~)\1\31ZiP:\245\273K\220n\245\33\244SB\244\273\21\1"..., 917804449, 732951090) = 917804449
pread64(5, "x^\354\335\5TU\353\342.|\220\20p\221\22\" \235\2\"% H#]\22\322\r\322-%"..., 909308379, 3146777046) = 909308379
pwrite64(5, "x^\354\335\5TU\353\342.|\220\20p\221\22\" \235\2\"% H#]\22\322\r\322-%"..., 917255929, 2840938583) = 917255929
pread64(5, "x^\354\275\5t\34Y\262\347-\306\224,fff\262\230\321B\213\331bK\262\230\31,\266\230\231"..., 23715679, 2199913800) = 23715679
pwrite64(5, "x^\354\275\5t\34Y\262\347-\306\224,fff\262\230\321B\213\331bK\262\230\31,\266\230\231"..., 23934582, 1650755539) = 23934582
pread64(5, "x^\354\275\5t\335X\226\367k\246(fffff\266c\306\230\231\231\0353\333\261\35C\2141"..., 24817697, 2223629479) = 24817697
pwrite64(5, "x^\354\275\5t\335X\226\367k\246(fffff\266c\306\230\231\231\0353\333\261\35C\2141"..., 25043550, 1674690121) = 25043550

It appears to be reading and writing large amounts of overlapping data to the output file (the offsets and write sizes do appear to overlap over time). Running the same strace on nccopy 4.7.3 shows that the writes are much smaller, and pread64 is never called. The majority of the increased runtime then appears in H5Z_pipeline, presumably compressing the data that is has read along with whatever data it was supposed to write. I'm afraid I'm not knowledgeable enough about the interaction between HDF5 and NetCDF to provide any suggestions, but please let me know if you need any further information or profiling data.

[WardF]

I believe this is the same issue as we've seen in #1757. I believe, at this point, the solution on our end will be to revert the default chunking parameters to 'safer' values, performance-wise. In the short term, you should be able to recompile netCDF-C and specify the parameter values from v4.7.3. Details are in the comment thread at #1757

[edwardhartnett]

But he reports that the same problem occurs when he changes the chunking parameters back.

@dsr900 can you confirm that you used the configure options to build netcdf-c with the older versions of the cache settings, and still saw this problem?

[WardF]

Good point Ed, I'm setting up a test to see if I can figure out what changed and where. I also want to see if maybe this is resolved by using a 1.10.6. No reason to expect it should make a difference but you never know.

[WardF]

@dsr900 My apologies for skimming the issue and missing that you had already tried the mitigation discussed in #1757. Thanks for providing such detailed steps, I'm currently working it into a test I can use in conjunction with git bisect to try to narrow down where the issue was introduced.

[edwardhartnett]

Also, I just read the title again and this is 64-bit offset format. So of course no change to HDF5 cache sizes can matter to it...

…

On Tue, Jun 23, 2020 at 3:29 PM Ward Fisher ***@***.***> wrote: @dsr900 <https://github.com/dsr900> My apologies for skimming the issue and missing that you had already tried the mitigation discussed in #1757 <#1757>. Thanks for providing such detailed steps, I'm currently working it into a test I can use in conjunction with git bisect to try to narrow down where the issue was introduced. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#1763 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AJIOMMA7DKFKO4JSW5U7RILRYENEJANCNFSM4OEENGZQ> .

Thanks for the responses everyone, I think I've found the culprit. I noticed that there was a difference in the output file sizes between the two versions of nccopy, so checked each with ncdump -s. The example file has 4 dimesions as follows:

dimensions:
j = 180 ;
i = 600 ;
time = UNLIMITED ; // (169 currently)
k = 47 ;  

From what I can tell, nccopy from v4.7.4 has set the chunk size for every variable to the size of its corresponding dimensions (i.e. one chunk per variable), whereas v4.7.3 has chunked over time and k. Here is the diff from ncdump -s -h on the file created by nccopy from v4.7.3 and v4.7.4

35c35
<               eta:_ChunkSizes = 1, 180, 600 ;
---
>               eta:_ChunkSizes = 169, 180, 600 ;
75c75
<               salt:_ChunkSizes = 1, 24, 90, 300 ;
---
>               salt:_ChunkSizes = 169, 47, 180, 600 ;
91c91
<               temp:_ChunkSizes = 1, 24, 90, 300 ;
---
>               temp:_ChunkSizes = 169, 47, 180, 600 ;
102c102
<               time:_ChunkSizes = 512 ;
---
>               time:_ChunkSizes = 169 ;
121c121
<               u:_ChunkSizes = 1, 24, 90, 300 ;
---
>               u:_ChunkSizes = 169, 47, 180, 600 ;
140c140
<               v:_ChunkSizes = 1, 24, 90, 300 ;
---
>               v:_ChunkSizes = 169, 47, 180, 600 ;
152c152
<               wspeed_u:_ChunkSizes = 1, 180, 600 ;
---
>               wspeed_u:_ChunkSizes = 169, 180, 600 ;
164c164
<               wspeed_v:_ChunkSizes = 1, 180, 600 ;
---
>               wspeed_v:_ChunkSizes = 169, 180, 600 ;
193c193
<               :_NCProperties = "version=2,netcdf=4.7.3,hdf5=1.10.5," ;
---
>               :_NCProperties = "version=2,netcdf=4.7.4,hdf5=1.10.5," ;

I then tried to approximate the v4.7.3 chunking structure in v4.7.4 by running nccopy -d 5 -s -c time/1,i/600,j/180,k/24 gbr4_simple_2016-06.nc.64 gbr4_simple_2016-06.nc.474c, and the runtime was reduced by a factor of 100 to 320 seconds. Furthermore, when using the v4.7.4 default chunk sizes with nccopy from v4.7.3, it takes significantly longer.

I guess this points to a change in the the way the default chunk size or default number of chunks in a variable is determined. Is this something that's able to be modified at configure time?

[DennisHeimbigner]

I diffed nccopy from the two versions.
I will have to take responsibility for this error. I changed the algorithm
in nccopy. The case is when an input file is classic and no chunking is specified
then it attempts to be too smart about choosing the chunksizes. I will revert the
behavior.

[DennisHeimbigner]

Apparently Ward's comment did not get inserted here.

Good morning all. The first 'bad' commit, as reported by git bisect, is 44d0dca. I provide this for context, and to see if it lines up with what you think, @DennisHeimbigner .

Short answer is no, this is not where I expected the failure to occur. Let me do some testing.

[DennisHeimbigner]

I expected the change that did this was the changes to the function
copy_chunking in the file ncdump/nccopy.c. About line 904
in the 4.7.4 version.

[WardF]

Hi Dennis, I removed my initial comment because testing is ongoing.

[DennisHeimbigner]

Attached is a new copy of ncdump/nccopy.c
I am trying to test it, but I need to construct a large dataset.
Can https://github.com/dsr900 or someone
rebuild using this nccopy and try it on http://dapds00.nci.org.au/thredds/fileServer/fx3/gbr4/gbr4_simple_2016-06.nc

attachment:
nccopy.zip

[Note replaced the attachment because I left on some debug output, this
one should be quieter.]

Hi Dennis

Thanks for this, I can confirm that the chunk settings are identical between the output files created by nccopy in v4.7.3 and modified nccopy you've provided. Runtime of the modified nccopy on gbr4_simple_2016-06.nc was 235 seconds.