all: investigate why the time before a response on a failed query is in the order of seconds meanwhile correct queries take milliseconds

[odeke-em]

While extensively testing this library and also benchmarking over the course of my work on observability, I noticed that whenever a bad query (say with a syntax error) is issued using these libraries, executing the finally block is on the order of seconds even using MockSpanner, but for working queries we are in the order of microseconds to milliseconds

async function databaseRunSelect1() {
        const startTime: bigint = process.hrtime.bigint();
        try {
          return await database.run('SELECT 1');
        } catch (e) {
          console.log('To catch', humanizeTime(process.hrtime.bigint() - startTime));
          return null;
        } finally {
          console.log('1Good done', humanizeTime(process.hrtime.bigint() - startTime));
        }
}

async function databaseRunSelect1BadSyntax() {
        const startTime: bigint = process.hrtime.bigint();
        try {
          return await database.run('SELECT 1p');
        } catch (e) {
          console.log('To catch', humanizeTime(process.hrtime.bigint() - startTime));
          return null;
        } finally {
          console.log('1Bad done', humanizeTime(process.hrtime.bigint() - startTime));
        }
}

const secondUnits = ['ns', 'µs', 'ms', 's'];
interface unitDivisor {
  unit: string;
  divisor: number;
}
const pastSecondUnits: unitDivisor[] = [
  {unit: 'min', divisor: 60},
  {unit: 'hr', divisor: 60},
  {unit: 'day', divisor: 24},
  {unit: 'week', divisor: 7},
  {unit: 'month', divisor: 30},
];
function humanizeTime(ns) {
  let value = Number(ns);
  for (const unit of secondUnits) {
    if (value < 1000) {
      return `${value.toFixed(3)} ${unit}`;
    }
    value /= 1000;
  }

  let i = 0;
  for (i = 0; i < pastSecondUnits.length; i++) {
    const unitPlusValue = pastSecondUnits[i];
    const unitName = unitPlusValue.unit;
    const divisor = unitPlusValue.divisor;
    if (value < divisor) {
      return `${value}${unitName}`;
    }
    value = value / divisor;
  }
  return `${value.toFixed(3)} ${pastSecondUnits[pastSecondUnits.length - 1][0]}`;
}

will print out

1G done 1.502 ms
1G done 1.430 ms
1G done 1.509 ms
1G done 1.517 ms
1G done 1.381 ms
1G done 1.430 ms

1B done 6.549 s
To catch 6.847 s
1B done 6.848 s
To catch 6.500 s
1B done 6.500 s
To catch 7.661 s
1B done 7.661 s

Maybe it is just a problem with Node.js but that's let to the maintainers of this library to examine if there is something wrong going on here. Most likely it could be due to the unconditional calls to this.begin() which keep retrying or something else but either way the time to resolve should be the same.

[surbhigarg92]

@odeke-em This works fine when the same query is executed against real Spanner. The execution time is similar for invalid and valid query.
This is an existing issue with Emulator where the response hangs for invalid queries . Similar behavior for mockspanner if the mock result is not defined for invalid query.

We already have a bug for the same issue. #2014

Marking this as duplicated