Skip to content

Commit

Permalink
chore: add RPC requests logging for RETH calls slower than GETH (#785)
Browse files Browse the repository at this point in the history 
* chore: add RPC requests logging for RETH calls slower than GETH

* switch-cae

* fix unit test
  • Loading branch information
@jsy1218
jsy1218 authored Jul 18, 2024
1 parent 44a4c39 commit e0fc934
Show file tree
Hide file tree
Showing 3 changed files with 94 additions and 28 deletions.
100 changes: 83 additions & 17 deletions lib/rpc/SingleJsonRpcProvider.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -178,12 +178,25 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
}
}

async evaluateLatency(methodName: string, ...args: any[]) {
async evaluateLatency(latency: number, methodName: string, ...args: any[]) {
this.log.debug(`${this.url}: Evaluate for latency... methodName: ${methodName}`)
this.logEvaluateLatency()
this.evaluatingLatency = true
try {
return await (this as any)[`${methodName}_EvaluateLatency`](...args)
switch (methodName) {
case CALL_METHOD_NAME:
const transaction: Deferrable<TransactionRequest> = args[0]
const blockTag: BlockTag | Promise<BlockTag> = args[1]

return await this.call_EvaluateLatency(transaction, blockTag, latency)
case SEND_METHOD_NAME:
const underlyingMethodName = args[0]
const params: Array<any> = args.splice(1)

return await this.send_EvaluateLatency(underlyingMethodName, params, latency)
default:
return await (this as any)[`${methodName}_EvaluateLatency`](...args)
}
} catch (error: any) {
this.log.error({ error }, `Encounter error for shadow evaluate latency call: ${JSON.stringify(error)}`)
// Swallow the error.
Expand Down Expand Up @@ -264,6 +277,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
callType: CallType,
fnName: string,
fn: (...args: any[]) => Promise<any>,
latency?: number,
...args: any[]
): Promise<any> {
this.log.debug(
Expand All @@ -284,6 +298,20 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
const result = await fn(...args)
perf.latencyInMs = Date.now() - perf.startTimestampInMs

// The provider latency we evaluate against should always be faster than the provider we are using in prod currently.
// If that's not the case, we need to log the RPC request payload to help debugging.
if (latency && perf.latencyInMs > latency) {
const evaluatedLatency = perf.latencyInMs
this.log.error(
{ latency, evaluatedLatency },
`Slower evaluated latency for provider ${
this.providerName
}. SingleJsonRpcProvider: wrappedFunctionCall: callType: ${callType}, provider: ${
this.url
}, fnName: ${fnName}, fn: ${fn}, args: ${JSON.stringify([...args])}`
)
}

return result
} catch (error: any) {
perf.succeed = false
Expand Down Expand Up @@ -346,7 +374,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
///////////////////// Begin of override functions /////////////////////

override getBlockNumber(): Promise<number> {
return this.wrappedFunctionCall(CallType.NORMAL, 'getBlockNumber', this._getBlockNumber.bind(this))
return this.wrappedFunctionCall(CallType.NORMAL, 'getBlockNumber', this._getBlockNumber.bind(this), undefined)
}

override getBlockWithTransactions(
Expand All @@ -356,20 +384,28 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
CallType.NORMAL,
'getBlockWithTransactions',
super.getBlockWithTransactions.bind(this),
undefined,
blockHashOrBlockTag
)
}

override getCode(addressOrName: string | Promise<string>, blockTag?: BlockTag | Promise<BlockTag>): Promise<string> {
return this.wrappedFunctionCall(CallType.NORMAL, 'getCode', super.getCode.bind(this), addressOrName, blockTag)
return this.wrappedFunctionCall(
CallType.NORMAL,
'getCode',
super.getCode.bind(this),
undefined,
addressOrName,
blockTag
)
}

override getGasPrice(): Promise<BigNumber> {
return this.wrappedFunctionCall(CallType.NORMAL, 'getGasPrice', super.getGasPrice.bind(this))
return this.wrappedFunctionCall(CallType.NORMAL, 'getGasPrice', super.getGasPrice.bind(this), undefined)
}

override getLogs(filter: Filter): Promise<Array<Log>> {
return this.wrappedFunctionCall(CallType.NORMAL, 'getLogs', super.getLogs.bind(this), filter)
return this.wrappedFunctionCall(CallType.NORMAL, 'getLogs', super.getLogs.bind(this), undefined, filter)
}

override getStorageAt(
Expand All @@ -381,14 +417,21 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
CallType.NORMAL,
'getStorageAt',
super.getStorageAt.bind(this),
undefined,
addressOrName,
position,
blockTag
)
}

override getTransaction(transactionHash: string | Promise<string>): Promise<TransactionResponse> {
return this.wrappedFunctionCall(CallType.NORMAL, 'getTransaction', super.getTransaction.bind(this), transactionHash)
return this.wrappedFunctionCall(
CallType.NORMAL,
'getTransaction',
super.getTransaction.bind(this),
undefined,
transactionHash
)
}

override getTransactionCount(
Expand All @@ -399,6 +442,7 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
CallType.NORMAL,
'getTransactionCount',
super.getTransactionCount.bind(this),
undefined,
addressOrName,
blockTag
)
Expand All @@ -409,23 +453,31 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
CallType.NORMAL,
'getTransactionReceipt',
super.getTransactionReceipt.bind(this),
undefined,
transactionHash
)
}

override lookupAddress(address: string | Promise<string>): Promise<string | null> {
return this.wrappedFunctionCall(CallType.NORMAL, 'lookupAddress', super.lookupAddress.bind(this), address)
return this.wrappedFunctionCall(
CallType.NORMAL,
'lookupAddress',
super.lookupAddress.bind(this),
undefined,
address
)
}

override resolveName(name: string | Promise<string>): Promise<string | null> {
return this.wrappedFunctionCall(CallType.NORMAL, 'resolveName', super.resolveName.bind(this), name)
return this.wrappedFunctionCall(CallType.NORMAL, 'resolveName', super.resolveName.bind(this), undefined, name)
}

override sendTransaction(signedTransaction: string | Promise<string>): Promise<TransactionResponse> {
return this.wrappedFunctionCall(
CallType.NORMAL,
'sendTransaction',
super.sendTransaction.bind(this),
undefined,
signedTransaction
)
}
Expand All @@ -439,19 +491,20 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
CallType.NORMAL,
'waitForTransaction',
super.waitForTransaction.bind(this),
undefined,
transactionHash,
confirmations,
timeout
)
}

override call(transaction: Deferrable<TransactionRequest>, blockTag?: BlockTag | Promise<BlockTag>): Promise<string> {
return this.wrappedFunctionCall(CallType.NORMAL, 'call', super.call.bind(this), transaction, blockTag)
return this.wrappedFunctionCall(CallType.NORMAL, 'call', super.call.bind(this), undefined, transaction, blockTag)
}

override send(method: string, params: Array<any>): Promise<any> {
this.logSendMetrod(method)
return this.wrappedFunctionCall(CallType.NORMAL, 'send', super.send.bind(this), method, params)
return this.wrappedFunctionCall(CallType.NORMAL, 'send', super.send.bind(this), undefined, method, params)
}

///////////////////// Begin of special functions /////////////////////
Expand All @@ -463,24 +516,37 @@ export class SingleJsonRpcProvider extends StaticJsonRpcProvider {
}

private getBlockNumber_EvaluateHealthiness(): Promise<number> {
return this.wrappedFunctionCall(CallType.HEALTH_CHECK, 'getBlockNumber', this._getBlockNumber.bind(this))
return this.wrappedFunctionCall(CallType.HEALTH_CHECK, 'getBlockNumber', this._getBlockNumber.bind(this), undefined)
}

// @ts-ignore
private getBlockNumber_EvaluateLatency(): Promise<number> {
return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'getBlockNumber', this._getBlockNumber.bind(this))
return this.wrappedFunctionCall(
CallType.LATENCY_EVALUATION,
'getBlockNumber',
this._getBlockNumber.bind(this),
undefined
)
}

// @ts-ignore
private call_EvaluateLatency(
transaction: Deferrable<TransactionRequest>,
blockTag?: BlockTag | Promise<BlockTag>
blockTag?: BlockTag | Promise<BlockTag>,
latency?: number
): Promise<string> {
return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'call', super.call.bind(this), transaction, blockTag)
return this.wrappedFunctionCall(
CallType.LATENCY_EVALUATION,
'call',
super.call.bind(this),
latency,
transaction,
blockTag
)
}

// @ts-ignore
private send_EvaluateLatency(method: string, params: Array<any>): Promise<any> {
return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'send', super.send.bind(this), method, params)
private send_EvaluateLatency(method: string, params: Array<any>, latency?: number): Promise<any> {
return this.wrappedFunctionCall(CallType.LATENCY_EVALUATION, 'send', super.send.bind(this), latency, method, params)
}
}
2 changes: 1 addition & 1 deletion lib/rpc/UniJsonRpcProvider.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -239,7 +239,7 @@ export class UniJsonRpcProvider extends StaticJsonRpcProvider {
// Within each provider latency shadow evaluation, we should do block I/O,
// because NodeJS runs in single thread, so it's important to make sure
// we benchmark the latencies correctly based on the single-threaded sequential evaluation.
const evaluatedProviderResponse = await provider[`evaluateLatency`](methodName, ...args)
const evaluatedProviderResponse = await provider[`evaluateLatency`](latency, methodName, ...args)
// below invocation does not make the call/send RPC return the correct data
// both call and send will return "0x" for some reason
// I have to change to above invocation to make call/send return geniun RPC response
Expand Down
20 changes: 10 additions & 10 deletions test/mocha/unit/rpc/UniJsonRpcProvider.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -704,9 +704,9 @@ describe('UniJsonRpcProvider', () => {
// Shadow evaluate call should be made
expect(spy0.callCount).to.equal(0)
expect(spy1.callCount).to.equal(1)
expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(spy2.callCount).to.equal(1)
expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber')

expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
Expand Down Expand Up @@ -746,9 +746,9 @@ describe('UniJsonRpcProvider', () => {
// Shadow evaluate call should be made
expect(spy0.callCount).to.equal(0)
expect(spy1.callCount).to.equal(1)
expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(spy2.callCount).to.equal(1)
expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber')

expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
Expand All @@ -774,10 +774,10 @@ describe('UniJsonRpcProvider', () => {
await uniProvider.getBlockNumber('sessionId')

expect(spy1.callCount).to.equal(1)
expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp + 16000)
expect(spy2.callCount).to.equal(1)
expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp + 16000)
})

Expand Down Expand Up @@ -822,9 +822,9 @@ describe('UniJsonRpcProvider', () => {

expect(spy0.callCount).to.equal(0)
expect(spy1.callCount).to.equal(5)
expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(spy2.callCount).to.equal(5)
expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber')

expect(uniProvider['providers'][1]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
expect(uniProvider['providers'][2]['lastLatencyEvaluationTimestampInMs']).equals(timestamp)
Expand Down Expand Up @@ -946,9 +946,9 @@ describe('UniJsonRpcProvider', () => {
// 0.4 < 0.5, Shadow evaluate call should be made
expect(spy0.callCount).to.equal(0)
expect(spy1.callCount).to.equal(1)
expect(spy1.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy1.getCalls()[0].lastArg).to.equal('getBlockNumber')
expect(spy2.callCount).to.equal(1)
expect(spy2.getCalls()[0].firstArg).to.equal('getBlockNumber')
expect(spy2.getCalls()[0].lastArg).to.equal('getBlockNumber')
})

it('Test use of healthCheckSampleProb', async () => {
Expand Down

0 comments on commit e0fc934

Please sign in to comment.