diff --git a/observability-test/benchmark.ts b/observability-test/benchmark.ts new file mode 100644 index 000000000..828838d7a --- /dev/null +++ b/observability-test/benchmark.ts @@ -0,0 +1,143 @@ +/*! + * Copyright 2024 Google LLC. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +const lessComparator = (a, b) => { + if (a < b) return -1; + if (a > b) return 1; + return 0; +}; + +/* + * runBenchmarks runs each of the functions in runners ${nRuns} times + * each time collecting RAM usage and time spent and then produces + * a map of functionNames to the percentiles of RAM usage and time spent. + */ +export async function runBenchmarks(runners: Function[], done: Function) { + const nRuns = 10000; + const benchmarkValues = {_totalRuns: nRuns}; + + let k = 0; + for (k = 0; k < runners.length; k++) { + const fn = runners[k]; + const functionName = fn.name; + const timeSpentL: bigint[] = []; + const ramL: number[] = []; + let i = 0; + + // Warm up runs to ensure stable behavior. + for (i = 0; i < 8; i++) { + const value = await fn(); + } + + for (i = 0; i < nRuns; i++) { + const startTime: bigint = process.hrtime.bigint(); + const startHeapUsedBytes: number = process.memoryUsage().heapUsed; + const value = await fn(); + timeSpentL.push(process.hrtime.bigint() - startTime); + ramL.push(process.memoryUsage().heapUsed - startHeapUsedBytes); + } + + timeSpentL.sort(lessComparator); + ramL.sort(lessComparator); + + benchmarkValues[functionName] = { + ram: percentiles(functionName, ramL, 'bytes'), + timeSpent: percentiles(functionName, timeSpentL, 'time'), + }; + } + + done(benchmarkValues); +} + +function percentiles(method, sortedValues, kind) { + const n = sortedValues.length; + const p50 = sortedValues[Math.floor(n * 0.5)]; + const p75 = sortedValues[Math.floor(n * 0.75)]; + const p90 = sortedValues[Math.floor(n * 0.9)]; + const p95 = sortedValues[Math.floor(n * 0.95)]; + const p99 = sortedValues[Math.floor(n * 0.99)]; + + return { + p50: p50, + p75: p75, + p90: p90, + p95: p95, + p99: p99, + p50_s: humanize(p50, kind), + p75_s: humanize(p75, kind), + p90_s: humanize(p90, kind), + p95_s: humanize(p95, kind), + p99_s: humanize(p99, kind), + }; +} + +function humanize(values, kind) { + let converterFn = humanizeTime; + if (kind === 'bytes') { + converterFn = humanizeBytes; + } + return converterFn(values); +} + +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) { + const sign: number = ns < 0 ? -1 : +1; + let value = Math.abs(Number(ns)); + for (const unit of secondUnits) { + if (value < 1000) { + return `${(sign * 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 `${sign * value}${unitName}`; + } + value = value / divisor; + } + return `${(sign * value).toFixed(3)}${pastSecondUnits[pastSecondUnits.length - 1][0]}`; +} + +const bytesUnits = ['B', 'kB', 'MB', 'GB', 'TB', 'PB', 'ExB']; +function humanizeBytes(b) { + const sign: number = b < 0 ? -1 : +1; + let value = Math.abs(b); + for (const unit of bytesUnits) { + if (value < 1024) { + return `${(sign * value).toFixed(3)}${unit}`; + } + value = value / 1024; + } + + return `${(sign * value).toFixed(3)}${bytesUnits[bytesUnits.length - 1]}`; +} +export {humanizeTime, humanizeBytes}; diff --git a/observability-test/comparisons.ts b/observability-test/comparisons.ts new file mode 100644 index 000000000..7bc8145fb --- /dev/null +++ b/observability-test/comparisons.ts @@ -0,0 +1,327 @@ +/*! + * Copyright 2024 Google LLC. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import * as assert from 'assert'; +import {grpc} from 'google-gax'; +import {google} from '../protos/protos'; +import {Database, Instance, Spanner} from '../src'; +import { + Database as DatabaseUntraced, + Instance as InstanceUntraced, + Spanner as SpannerUntraced, +} from '@google-cloud/spanner'; +import protobuf = google.spanner.v1; +import * as mock from '../test/mockserver/mockspanner'; +import * as mockInstanceAdmin from '../test/mockserver/mockinstanceadmin'; +import * as mockDatabaseAdmin from '../test/mockserver/mockdatabaseadmin'; +const { + AlwaysOnSampler, + NodeTracerProvider, + InMemorySpanExporter, +} = require('@opentelemetry/sdk-trace-node'); +const {SimpleSpanProcessor} = require('@opentelemetry/sdk-trace-base'); +import {humanizeBytes, humanizeTime, runBenchmarks} from './benchmark'; + +const {ObservabilityOptions} = require('../src/instrument'); + +const selectSql = 'SELECT 1'; +const updateSql = 'UPDATE FOO SET BAR=1 WHERE BAZ=2'; + +/** A simple result set for SELECT 1. */ +function createSelect1ResultSet(): protobuf.ResultSet { + const fields = [ + protobuf.StructType.Field.create({ + name: 'NUM', + type: protobuf.Type.create({code: protobuf.TypeCode.INT64}), + }), + ]; + const metadata = new protobuf.ResultSetMetadata({ + rowType: new protobuf.StructType({ + fields, + }), + }); + return protobuf.ResultSet.create({ + metadata, + rows: [{values: [{stringValue: '1'}]}], + }); +} + +interface setupResults { + server: grpc.Server; + spanner: Spanner | SpannerUntraced; + spannerMock: mock.MockSpanner; +} + +async function setup( + traced: boolean, + observabilityOptions?: typeof ObservabilityOptions +): Promise { + const server = new grpc.Server(); + + const spannerMock = mock.createMockSpanner(server); + mockInstanceAdmin.createMockInstanceAdmin(server); + mockDatabaseAdmin.createMockDatabaseAdmin(server); + + const port: number = await new Promise((resolve, reject) => { + server.bindAsync( + '0.0.0.0:0', + grpc.ServerCredentials.createInsecure(), + (err, assignedPort) => { + if (err) { + reject(err); + } else { + resolve(assignedPort); + } + } + ); + }); + + spannerMock.putStatementResult( + selectSql, + mock.StatementResult.resultSet(createSelect1ResultSet()) + ); + spannerMock.putStatementResult( + updateSql, + mock.StatementResult.updateCount(1) + ); + + let spanner: Spanner | SpannerUntraced; + + if (traced) { + spanner = new Spanner({ + projectId: 'observability-project-id', + servicePath: 'localhost', + port, + sslCreds: grpc.credentials.createInsecure(), + observabilityOptions: observabilityOptions, + }); + } else { + spanner = new SpannerUntraced({ + projectId: 'observability-project-id', + servicePath: 'localhost', + port, + sslCreds: grpc.credentials.createInsecure(), + }); + } + + return Promise.resolve({ + spanner: spanner, + server: server, + spannerMock: spannerMock, + }); +} + +describe('Benchmarking', () => { + if (!process.env.SPANNER_RUN_BENCHMARKS) { + console.log( + 'Skipping micro-benchmarking because SPANNER_RUN_BENCHMARKS is not set' + ); + return; + } + + async function setItUp( + traced: boolean, + withExporters?: boolean + ): Promise> { + // Setup firstly. + let observabilityOptions: typeof ObservabilityOptions = null; + if (withExporters) { + const traceExporter = new InMemorySpanExporter(); + const sampler = new AlwaysOnSampler(); + const provider = new NodeTracerProvider({ + sampler: sampler, + exporter: traceExporter, + }); + provider.addSpanProcessor(new SimpleSpanProcessor(traceExporter)); + + observabilityOptions = { + tracerProvider: provider, + enableExtendedTracing: true, + } as typeof ObservabilityOptions; + } + + const setupResult = await setup(traced, observabilityOptions); + const spanner = setupResult.spanner; + const instance = spanner.instance('instance'); + const database = instance.database('database'); + const server = setupResult.server; + + after(async () => { + if (observabilityOptions) { + await observabilityOptions.tracerProvider!.shutdown(); + } + database.close(); + spanner.close(); + server.tryShutdown(() => {}); + }); + + const runners: Function[] = [ + async function databaseRunSelect1AsyncAwait() { + if (traced) { + const [rows] = await (database as Database).run('SELECT 1'); + for (const row of rows) { + var _ = row; + } + return rows; + } else { + const [rows] = await (database as DatabaseUntraced).run('SELECT 1'); + for (const row of rows) { + var _ = row; + } + return rows; + } + }, + + async function databaseRunSelect1Callback() { + return new Promise((resolve, reject) => { + const callback = (err, rows) => { + if (err) { + reject(err); + return; + } + + for (const row of rows) { + const _ = row; + } + resolve(rows); + }; + + if (traced) { + (database as Database).run('SELECT 1', callback); + } else { + (database as DatabaseUntraced).run('SELECT 1', callback); + } + }); + }, + + /* + async function databaseGetTransactionAsync() { + const tx = await database.getTransction(); + + try { + await tx!.begin(); + return await tx!.runUpdate(updateSql); + } catch (e) { + console.log(e); + return null; + } finally { + console.log('tx.end'); + tx!.end(); + console.log('exiting'); + } + }, + */ + async function databaseRunTransactionAsyncTxRunUpdate() { + const withTx = async tx => { + await tx!.begin(); + const result = await tx!.runUpdate(updateSql); + tx!.end(); + return result; + }; + + try { + if (traced) { + return await (database as Database).runTransactionAsync(withTx); + } else { + return await (database as DatabaseUntraced).runTransactionAsync( + withTx + ); + } + } catch (e) { + return null; + } + }, + + async function databaseRunTransactionAsyncTxRun() { + const withTx = async tx => { + await tx!.begin(); + const result = await tx!.runUpdate('SELECT 1'); + tx!.end(); + return result; + }; + + try { + if (traced) { + return await (database as Database).runTransactionAsync(withTx); + } else { + return await (database as DatabaseUntraced).runTransactionAsync( + withTx + ); + } + } catch (e) { + return null; + } + }, + ]; + + return new Promise(resolve => { + runBenchmarks(runners, results => { + resolve(results); + }); + }); + } + + interface percentiles { + p50: number; + p50_s: string; + } + + interface description { + ram: percentiles; + timeSpent: percentiles; + } + + it('Database runs compared', async () => { + const traced = await setItUp(true); + const untraced = await setItUp(false); + const tracedWithOTELOn = await setItUp(true, true); + + console.log(`Total Runs: ${traced['_totalRuns']}`); + for (const tracedM in traced) { + const tracedV = traced[tracedM]; + if (typeof tracedV !== 'object') { + continue; + } + const tracedMethod = tracedM as string; + const tracedValue = tracedV as description; + const untracedValue = untraced[tracedMethod] as description; + const tracedWithOTELValue = tracedWithOTELOn[tracedMethod] as description; + const tracedRAM = tracedValue!.ram; + const tracedWithOTELRAM = tracedWithOTELValue!.ram; + const untracedRAM = untracedValue!.ram; + console.log(`${tracedMethod}`); + console.log( + `\tRAM Untraced(${untracedRAM.p50_s}) vs Traced (${tracedRAM.p50_s}): increase by (${humanizeBytes(tracedRAM.p50 - untracedRAM.p50)}) or ${percentDiff(untracedRAM.p50, tracedRAM.p50).toFixed(2)}%` + ); + console.log( + `\tRAM Untraced(${untracedRAM.p50_s}) vs Traced+OTEL(${tracedWithOTELRAM.p50_s}): increase by (${humanizeBytes(tracedWithOTELRAM.p50 - untracedRAM.p50)}) or ${percentDiff(untracedRAM.p50, tracedWithOTELRAM.p50).toFixed(2)}%` + ); + const tracedTime = tracedValue.timeSpent; + const tracedWithOTELTime = tracedWithOTELValue.timeSpent; + const untracedTime = untracedValue.timeSpent; + console.log( + `\tTime Untraced(${untracedTime.p50_s}) vs Traced (${tracedTime.p50_s}): increase by (${humanizeTime(tracedTime.p50 - untracedTime.p50)}) or ${percentDiff(untracedTime.p50, tracedTime.p50).toFixed(2)}%` + ); + console.log( + `\tTime Untraced(${untracedTime.p50_s}) vs Traced+OTEL(${tracedWithOTELTime.p50_s}): increase by (${humanizeTime(tracedWithOTELTime.p50 - untracedTime.p50)}) or ${percentDiff(untracedTime.p50, tracedWithOTELTime.p50).toFixed(2)}%\n` + ); + } + }); +}); + +function percentDiff(orig, fresh) { + return ((Number(fresh) - Number(orig)) * 100.0) / Number(orig); +} diff --git a/observability-test/spanner.ts b/observability-test/spanner.ts index 2e90b3044..78cab0e3b 100644 --- a/observability-test/spanner.ts +++ b/observability-test/spanner.ts @@ -44,6 +44,8 @@ const { const { AsyncHooksContextManager, } = require('@opentelemetry/context-async-hooks'); +import {promisify} from '@google-cloud/promisify'; +import {runBenchmarks} from './benchmark'; const {ObservabilityOptions} = require('../src/instrument'); import {SessionPool} from '../src/session-pool'; diff --git a/package.json b/package.json index 27ed2f743..9afa6b556 100644 --- a/package.json +++ b/package.json @@ -33,7 +33,7 @@ "samples-test-with-archived": "cd samples/ && npm link ../ && npm test-with-archived && cd ../", "samples-test": "cd samples/ && npm link ../ && npm test && cd ../", "system-test": "mocha build/system-test --timeout 1600000", - "observability-test": "mocha build/observability-test --timeout 1600000", + "observability-test": "mocha build/observability-test --timeout 1600000 -g 'Benchmarking'", "cleanup": "mocha scripts/cleanup.js --timeout 30000", "test": "mocha build/test build/test/common build/observability-test", "ycsb": "node ./benchmark/ycsb.js run -P ./benchmark/workloada -p table=usertable -p cloudspanner.instance=ycsb-instance -p operationcount=100 -p cloudspanner.database=ycsb", @@ -58,6 +58,7 @@ "@google-cloud/precise-date": "^4.0.0", "@google-cloud/projectify": "^4.0.0", "@google-cloud/promisify": "^4.0.0", + "@google-cloud/spanner": "^7.14.0", "@grpc/proto-loader": "^0.7.0", "@opentelemetry/api": "^1.9.0", "@opentelemetry/context-async-hooks": "^1.26.0",