Performance regression with 'nc_get_att' in v4.9.1

[abhibaruah]

NetCDF version: v4.9.1
OS: Debian 10 (but reproducible in Windows and MacOS)

We recently upgraded from netCDF v4.8.1 to v4.9.1, and after the upgrade, we saw that some of our tests for NC_VLEN attribute reading have regressed significantly. I am attaching a repro code for the NC_VLEN attribute reading. Specifically, the regressions are seen in the function 'nc_get_att'.

The base type for the example is NC_BYTE, but we could also see the similar regressions with other base types as well (NC_CHAR, NC_DOUBLE, NC_USHORT, NC_STRING, etc).

Is this regression intended due to some change in the source code of 'nc_get_att' ?

Please find repro code and the results below. You can find the nc file I used for the repro here.

netCDF v4.9.1 time: 321.6 microseconds
netCDF v4.8.1 time: 19 microseconds

#include <stdio.h>
#include <string.h>
#include <netcdf.h>
#include <chrono>
#include <iostream>

using namespace std::chrono;

#define FILENAME "NetcdfNcVlenTypesPerfFile.nc"
#define GRPNAME "numeric_types"
#define VAR "samples_int8"
#define ATTNAME "attribute_int8"

int main()
{
    int ncid;
    int grpid;
    int varid, status;
    
	// Reopen the file and inquire the variable
	status = nc_open(FILENAME, NC_NOWRITE, &ncid);
	printf("status after nc_open = %d\n", status);
	
	status = nc_inq_ncid(ncid, GRPNAME, &grpid);
	printf("status after nc_inq_ncid = %d\n", status);
	
	status = nc_inq_varid(grpid, VAR, &varid);
	printf("status after nc_inq_varid = %d\n", status);
	
	
	
	nc_type datatype;
	size_t attr_length;
	
	status = nc_inq_att ( grpid, varid, ATTNAME, &datatype, &attr_length );
	printf("status after nc_inq_att = %d\n", status);
	
	nc_type base_type;
	status = nc_inq_vlen(grpid, datatype, NULL, NULL, &base_type);
	printf("status after nc_inq_vlen = %d\n", status);
	
	double time;
	double sum = 0;
	
	for (int i = 0; i < 1000; i++)
	{
		nc_vlen_t* data = new nc_vlen_t[attr_length];
		
		auto start = high_resolution_clock::now();
		status = nc_get_att(grpid, varid, ATTNAME, data);
		auto stop = high_resolution_clock::now();
		auto duration = duration_cast<microseconds>(stop - start);
		
		time = duration.count();
		sum = sum + time;

                status = nc_free_vlens(attr_length, data);
                delete[] data;
	}
	
	double tavg = sum/1000;
	std::cout << "Avg Time: " << tavg <<std::endl;
    
	// close the file 
	status = nc_close(ncid);
	printf("status code after close = %d\n", status);
	printf("End of test.\n\n");

    return 0;
}

[WardF]

Indeed, that's pretty significant. Let me take a look. Did the underlying versions of libhdf5 change as part of the upgrade, and if so, can you confirm which versions were in use?

[abhibaruah]

The hdf5 library version is the same.
We are using v1.10.8

[DennisHeimbigner]

Without looking, my speculation is that this is related to this PR: #2179.

[DennisHeimbigner]

Did a quick gprof check; result below.
The leading time consumers are related to the above mentioned PR.

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
 46.94      0.23     0.23                             read_align
 10.20      0.28     0.05                             copy_datar
  8.16      0.32     0.04                             NC4_inq_atomic_type
  8.16      0.36     0.04                             copy_vlen
  4.08      0.38     0.02                             NC4_inq_user_type
  4.08      0.40     0.02                             NC_inq_any_type
  4.08      0.42     0.02                             nc4_find_nc_grp_h5
  4.08      0.44     0.02                             nc_log
  2.04      0.45     0.01                             NC4_inq_type_fixed_size
  2.04      0.46     0.01                             _init
  2.04      0.47     0.01                             find_in_NCList
  2.04      0.48     0.01                             nc4_check_name
  2.04      0.49     0.01                             nclistget

[DennisHeimbigner]

I can improve the performance somewhat by optimizing for special (hopefully common) cases.
Note that your current code potentially has big memory leaks.

[abhibaruah]

Thanks for taking a look Dennis.
I am aware that the repro code I pasted for the example has memory leaks. I apologize for that.
I hastily put it together this morning since I am also working towards a deadline and have some other bugs on my plate.

I will try and fix the repro code later this week once I free up a bit.

Regarding the improvement for the performance, I am guessing that you will target it for the next release of netCDF. Is that correct?

[DennisHeimbigner]

I will try to get it into the next release. But I cannot promise that it will happen.
There are a couple of higher priority items I need to complete.

[DennisHeimbigner]

Partly fixed by PR #2699.
This PR provides significant performance improvement, but it is still
not as fast as it was in 4.8.1, but this solution is more general.