Skip to content

Add detailed durations for each process section #415

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
rouzwelt merged 1 commit into from
Nov 9, 2025
Merged

Add detailed durations for each process section #415

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
64 changes: 64 additions & 0 deletions src/core/process/order.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -107,6 +107,8 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.order"]).toEqual("0xid");
expect(result.value.spanAttributes["details.pair"]).toBe("BUY/SELL");
expect(result.value.spanAttributes["details.orderbook"]).toEqual("0xorderbook");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.endTime).toBeTypeOf("number");

// ensure pair maps are updated on quote 0
Expand Down Expand Up @@ -134,6 +136,8 @@ describe("Test processOrder", () => {
expect(result.error.spanAttributes["details.pair"]).toBe("BUY/SELL");
expect(result.error.spanAttributes["details.orderbook"]).toEqual("0xorderbook");
expect(result.error.endTime).toBeTypeOf("number");
expect(result.error.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["event.quoteOrder"]).toHaveLength(2);

// ensure pair maps are updated on quote failure
expect(mockOrderManager.removeFromPairMaps).toHaveBeenCalledWith(mockArgs.orderDetails);
Expand Down Expand Up @@ -223,6 +227,16 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.inputToEthPrice"]).toBe("100");
expect(result.value.spanAttributes["details.outputToEthPrice"]).toBe("no-way");
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getEthMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getEthMarketPrice"]).toHaveLength(2);
});

it('should set outputToEthPrice to "0" if getMarketPrice returns undefined for output and gasCoveragePercentage is "0"', async () => {
Expand Down Expand Up @@ -254,6 +268,16 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.inputToEthPrice"]).toBe("100");
expect(result.value.spanAttributes["details.outputToEthPrice"]).toBe("0");
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getEthMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getEthMarketPrice"]).toHaveLength(2);
});

it('should return FailedToGetEthPrice if getMarketPrice returns undefined and gasCoveragePercentage is not "0"', async () => {
Expand All @@ -279,6 +303,12 @@ describe("Test processOrder", () => {
expect(result.error.spanAttributes["details.pair"]).toBe("BUY/SELL");
expect(result.error.spanAttributes["details.orderbook"]).toEqual("0xorderbook");
expect(result.error.endTime).toBeTypeOf("number");
expect(result.error.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.error.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.error.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
});

it('should set input/outputToEthPrice to "0" if getMarketPrice returns undefined and gasCoveragePercentage is "0"', async () => {
Expand Down Expand Up @@ -306,6 +336,16 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.pair"]).toBe("BUY/SELL");
expect(result.value.spanAttributes["details.orderbook"]).toEqual("0xorderbook");
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getEthMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getEthMarketPrice"]).toHaveLength(2);
});

it("should return ok result if findBestTrade throws with noneNodeError", async () => {
Expand Down Expand Up @@ -338,6 +378,18 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.noneNodeError"]).toBe(true);
expect(result.value.spanAttributes["details.test"]).toBe("something");
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getEthMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getEthMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.findBestTrade"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.findBestTrade"]).toHaveLength(2);
});

it("should return ok result if findBestTrade throws without noneNodeError", async () => {
Expand Down Expand Up @@ -370,6 +422,18 @@ describe("Test processOrder", () => {
expect(result.value.spanAttributes["details.noneNodeError"]).toBe(false);
expect(result.value.spanAttributes["details.test"]).toBe("something");
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.duration.quoteOrder"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.quoteOrder"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getPairMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getPairMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.getEthMarketPrice"]).toBeGreaterThan(
0,
);
expect(result.value.spanAttributes["event.getEthMarketPrice"]).toHaveLength(2);
expect(result.value.spanAttributes["details.duration.findBestTrade"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.findBestTrade"]).toHaveLength(2);
});

it("should proceed to processTransaction if all steps succeed (happy path)", async () => {
Expand Down
36 changes: 30 additions & 6 deletions src/core/process/order.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -59,14 +59,17 @@ export async function processOrder(
spanAttributes["details.pair"] = tokenPair;
spanAttributes["details.orderbook"] = orderDetails.orderbook;

spanAttributes["event.quoteOrder"] = performance.now();
const quoteOrderTime = performance.now();
try {
await this.orderManager.quoteOrder(orderDetails);
if (orderDetails.takeOrder.quote?.maxOutput === 0n) {
// remove from pair maps if quote fails, to keep the pair map list free
// of orders with 0 maxoutput this will make counterparty lookups faster
this.orderManager.removeFromPairMaps(orderDetails);
const endTime = performance.now();
const quoteOrderDuration = endTime - quoteOrderTime;
spanAttributes["details.duration.quoteOrder"] = quoteOrderDuration;
spanAttributes["event.quoteOrder"] = [quoteOrderTime, quoteOrderDuration];
return async () => {
return Result.ok({
...baseResult,
Expand All @@ -80,6 +83,9 @@ export async function processOrder(
} catch (e) {
this.orderManager.removeFromPairMaps(orderDetails);
const endTime = performance.now();
const quoteOrderDuration = endTime - quoteOrderTime;
spanAttributes["details.duration.quoteOrder"] = quoteOrderDuration;
spanAttributes["event.quoteOrder"] = [quoteOrderTime, quoteOrderDuration];
return async () =>
Result.err({
...baseResult,
Expand All @@ -90,6 +96,9 @@ export async function processOrder(
}

// record order quote details in span attributes
const quoteOrderDuration = performance.now() - quoteOrderTime;
spanAttributes["details.duration.quoteOrder"] = quoteOrderDuration;
spanAttributes["event.quoteOrder"] = [quoteOrderTime, quoteOrderDuration];
spanAttributes["details.quote"] = JSON.stringify({
maxOutput: formatUnits(orderDetails.takeOrder.quote!.maxOutput, 18),
ratio: formatUnits(orderDetails.takeOrder.quote!.ratio, 18),
Expand Down Expand Up @@ -143,7 +152,7 @@ export async function processOrder(
}

// record market price in span attributes
spanAttributes["event.getPairMarketPrice"] = performance.now();
const getPairMarketPriceTime = performance.now();
const marketPriceResult = await this.state.getMarketPrice(
fromToken,
toToken,
Expand All @@ -155,9 +164,15 @@ export async function processOrder(
parseUnits(marketPriceResult.value.price, 18),
);
}
const getPairMarketPriceDuration = performance.now() - getPairMarketPriceTime;
spanAttributes["details.duration.getPairMarketPrice"] = getPairMarketPriceDuration;
spanAttributes["event.getPairMarketPrice"] = [
getPairMarketPriceTime,
getPairMarketPriceDuration,
];

// get in/out tokens to eth price
spanAttributes["event.getEthMarketPrice"] = performance.now();
const getEthMarketPriceTime = performance.now();
let inputToEthPrice = "";
let outputToEthPrice = "";
const inputToEthPriceResult = await this.state.getMarketPrice(
Expand Down Expand Up @@ -204,8 +219,11 @@ export async function processOrder(
spanAttributes["details.gasPriceL1"] = this.state.l1GasPrice.toString();
}
spanAttributes["gasPriceMultiplier"] = this.state.gasPriceMultiplier;
const getEthMarketPriceDuration = performance.now() - getEthMarketPriceTime;
spanAttributes["details.duration.getEthMarketPrice"] = getEthMarketPriceDuration;
spanAttributes["event.getEthMarketPrice"] = [getEthMarketPriceTime, getEthMarketPriceDuration];

spanAttributes["event.findBestTrade"] = performance.now();
const findBestTradeTime = performance.now();
const trade = await this.findBestTrade({
orderDetails,
signer,
Expand All @@ -214,10 +232,11 @@ export async function processOrder(
inputToEthPrice,
outputToEthPrice,
});
const endTime = performance.now();
if (trade.isErr()) {
const result: ProcessOrderSuccess = {
...baseResult,
endTime: performance.now(),
endTime,
};
// record all span attributes
for (const attrKey in trade.error.spanAttributes) {
Expand All @@ -229,6 +248,9 @@ export async function processOrder(
} else {
spanAttributes["details.noneNodeError"] = false;
}
const findBestTradeDuration = endTime - findBestTradeTime;
spanAttributes["details.duration.findBestTrade"] = findBestTradeDuration;
spanAttributes["event.findBestTrade"] = [findBestTradeTime, findBestTradeDuration];
return async () => Result.ok(result);
}

Expand All @@ -246,6 +268,9 @@ export async function processOrder(
spanAttributes[attrKey] = trade.value.spanAttributes[attrKey];
}
}
const findBestTradeDuration = endTime - findBestTradeTime;
spanAttributes["details.duration.findBestTrade"] = findBestTradeDuration;
spanAttributes["event.findBestTrade"] = [findBestTradeTime, findBestTradeDuration];

// get block number
let blockNumber: number;
Expand All @@ -263,7 +288,6 @@ export async function processOrder(
}

// process the found transaction opportunity
spanAttributes["event.processTransaction"] = performance.now();
return processTransaction({
rawtx,
signer,
Expand Down
12 changes: 8 additions & 4 deletions src/core/process/receipt.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -117,7 +117,8 @@ describe("Test processReceipt", () => {
expect(result.value.spanAttributes["details.netProfit"]).toBeDefined();
expect(result.value.spanAttributes["details.netProfit"]).toBeTypeOf("number");
expect(result.value.spanAttributes["details.gasCostL1"]).toBeUndefined();
expect(result.value.spanAttributes["details.mineTime"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["details.duration.transaction"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.transaction"]).toHaveLength(2);
});

it("should calculate gas cost correctly including L1 fee", async () => {
Expand Down Expand Up @@ -149,7 +150,8 @@ describe("Test processReceipt", () => {
expect(result.value.inputTokenIncome).toBeUndefined();
expect(result.value.outputTokenIncome).toBeUndefined();
expect(result.value.endTime).toBeTypeOf("number");
expect(result.value.spanAttributes["details.mineTime"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["details.duration.transaction"]).toBeGreaterThan(0);
expect(result.value.spanAttributes["event.transaction"]).toHaveLength(2);
});
});

Expand All @@ -174,7 +176,8 @@ describe("Test processReceipt", () => {
expect(result.error.error).toBe(mockSimulation);
expect(result.error.txUrl).toBe(mockArgs.txUrl);
expect(result.error.spanAttributes["txNoneNodeError"]).toBe(true);
expect(result.error.spanAttributes["details.mineTime"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["details.duration.transaction"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["event.transaction"]).toHaveLength(2);
expect(result.error.endTime).toBeTypeOf("number");
});

Expand Down Expand Up @@ -210,7 +213,8 @@ describe("Test processReceipt", () => {

assert(result.isErr());
expect(result.error.spanAttributes["txNoneNodeError"]).toBe(false);
expect(result.error.spanAttributes["details.mineTime"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["details.duration.transaction"]).toBeGreaterThan(0);
expect(result.error.spanAttributes["event.transaction"]).toHaveLength(2);
expect(result.error.endTime).toBeTypeOf("number");
});

Expand Down
6 changes: 5 additions & 1 deletion src/core/process/receipt.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,11 @@ export async function processReceipt({
}: ProcessReceiptArgs): Promise<Result<ProcessOrderSuccess, ProcessOrderFailure>> {
const l1Fee = getL1Fee(receipt);
const gasCost = receipt.effectiveGasPrice * receipt.gasUsed + l1Fee;
baseResult.spanAttributes["details.mineTime"] = performance.now() - txSendTime;

// record transaction time
const txMineDuration = performance.now() - txSendTime;
baseResult.spanAttributes["details.duration.transaction"] = txMineDuration;
baseResult.spanAttributes["event.transaction"] = [txSendTime, txMineDuration];

// keep track of gas consumption of the account and bounty token
baseResult.gasCost = gasCost;
Expand Down
18 changes: 12 additions & 6 deletions src/core/process/round.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -806,7 +806,10 @@ describe("Test finalizeRound", () => {
const mockSettle = vi.fn().mockResolvedValue(
Result.ok({
status: ProcessOrderStatus.FoundOpportunity,
spanAttributes: { "event.something": 1234, "event.another": 5678 },
spanAttributes: {
"event.something": [1234, 456],
"event.another": [5678, 123],
},
endTime: 789,
}),
);
Expand All @@ -822,8 +825,8 @@ describe("Test finalizeRound", () => {
const addEventSpy = vi.spyOn(PreAssembledSpan.prototype, "addEvent");
await finalizeRound.call(mockSolver, settlements);

expect(addEventSpy).toHaveBeenCalledWith("something", undefined, 1234);
expect(addEventSpy).toHaveBeenCalledWith("another", undefined, 5678);
expect(addEventSpy).toHaveBeenCalledWith("something", { duration: 456 }, 1234);
expect(addEventSpy).toHaveBeenCalledWith("another", { duration: 123 }, 5678);

addEventSpy.mockRestore();
});
Expand Down Expand Up @@ -1337,7 +1340,10 @@ describe("Test finalizeRound", () => {
const mockSettle = vi.fn().mockResolvedValue(
Result.err({
reason: "unknown_reason",
spanAttributes: { "event.something": 1234, "event.another": 5678 },
spanAttributes: {
"event.something": [1234, 456],
"event.another": [5678, 123],
},
status: "failed",
error: new Error("unexpected"),
endTime: 789,
Expand All @@ -1355,8 +1361,8 @@ describe("Test finalizeRound", () => {
const addEventSpy = vi.spyOn(PreAssembledSpan.prototype, "addEvent");
await finalizeRound.call(mockSolver, settlements);

expect(addEventSpy).toHaveBeenCalledWith("something", undefined, 1234);
expect(addEventSpy).toHaveBeenCalledWith("another", undefined, 5678);
expect(addEventSpy).toHaveBeenCalledWith("something", { duration: 456 }, 1234);
expect(addEventSpy).toHaveBeenCalledWith("another", { duration: 123 }, 5678);

addEventSpy.mockRestore();
});
Expand Down
10 changes: 6 additions & 4 deletions src/core/process/round.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -200,10 +200,11 @@ export async function finalizeRound(
for (const attrKey in value.spanAttributes) {
// record event attrs
if (attrKey.startsWith("event.")) {
const _event = value.spanAttributes[attrKey] as number[];
report.addEvent(
attrKey.replace("event.", ""),
undefined,
value.spanAttributes[attrKey] as number,
{ duration: _event[1] },
_event[0] as number,
);
delete value.spanAttributes[attrKey];
}
Expand Down Expand Up @@ -245,10 +246,11 @@ export async function finalizeRound(
for (const attrKey in err.spanAttributes) {
// record event attrs
if (attrKey.startsWith("event.")) {
const _event = err.spanAttributes[attrKey] as number[];
report.addEvent(
attrKey.replace("event.", ""),
undefined,
err.spanAttributes[attrKey] as number,
{ duration: _event[1] },
_event[0] as number,
);
delete err.spanAttributes[attrKey];
}
Expand Down
Loading