Page MenuHomePhabricator

Add in tracking (and graphs) for how long api calls to the payment processors take
Closed, ResolvedPublic

Description

Goal
Add consistent, comparable timing logs for outbound payment-provider API/SDK calls so we can monitor performance and troubleshoot slowdowns across providers and payment methods.

Approach

  • Introduce shared timing behaviour
    • Add an ApiTimings utility to build a standard tag format and emit a single timing log line.
    • Store the selected payment method on ProviderConfiguration (via provider factory) so timing code can read it from Context.
  • Add a reusable timing wrapper
    • Add ApiTimingTrait::timedCall() to wrap a callable, measure elapsed time, and log in a finally block (so failures still get timed).
    • Derive processor name from namespace and map provider-specific method names to canonical operations via ApiOperation.
  • Instrument provider API classes
    • Wrap outbound calls in provider API methods using timedCall(__FUNCTION__, fn () => ...).
    • Add/extend ApiOperation mappings for each provider so timing tags use canonical operations.

Results

  • Consistent timing log tags across providers and methods:
    • Format: [processor|paymentMethod|apiOperation|request|time] <seconds>
    • Example: [gravy|cc|authorize|request|time] 1.234567s
    • Example: [adyen|cc|authorize|request|time] 1.234567s
    • Example: [dlocal|cc|authorize|request|time] 1.234567s
    • Example: [braintree|venmo|createsession|request|time] 0.152466s
  • Coverage to emit timings for outbound calls added to:
    • Gravy
    • Adyen
    • dLocal
    • PayPal
    • Braintree
  • Provider-specific method mappings added to ApiOperation, ensuring canonical operation names (e.g., authorise, capture, refund, cancel) regardless of provider method naming.
  • Tests added/updated for timing utilities/mapping behaviour to keep tags and operation mapping consistent over time.

Event Timeline

Change #1217280 had a related patch set uploaded (by Ejegg; author: Ejegg):

[wikimedia/fundraising/SmashPig@master] Add Gravy SDK wrapper for API timings

https://gerrit.wikimedia.org/r/1217280

Change #1219168 had a related patch set uploaded (by Ejegg; author: Ejegg):

[wikimedia/fundraising/SmashPig@master] Add elapsed time to CurlWrapper return array

https://gerrit.wikimedia.org/r/1219168

Change #1219175 had a related patch set uploaded (by Ejegg; author: Ejegg):

[wikimedia/fundraising/SmashPig@master] Add API call timings to Adyen calls

https://gerrit.wikimedia.org/r/1219175

Change #1217280 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add Gravy SDK wrapper for API timings

https://gerrit.wikimedia.org/r/1217280

Change #1219168 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add elapsed time to CurlWrapper return array

https://gerrit.wikimedia.org/r/1219168

Change #1219175 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add API call timings to Adyen calls

https://gerrit.wikimedia.org/r/1219175

Change #1219647 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Add ApiTimings utility for standardised API timing logs

https://gerrit.wikimedia.org/r/1219647

Change #1220646 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Add ApiTimingTrait to standardise API call timing logs.

https://gerrit.wikimedia.org/r/1220646

Change #1223718 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Behaviour: Emit ApiTimings for Gravy API calls

https://gerrit.wikimedia.org/r/1223718

Change #1223742 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Behaviour: Emit ApiTimings for Adyen API calls

https://gerrit.wikimedia.org/r/1223742

Change #1224658 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Structure: Add ApiOperation enum to canonicalise API timing operation names

https://gerrit.wikimedia.org/r/1224658

Canonicalise API Operations?

The Problem:
Different payment processors use different names for the same logical operations:

  • Adyen: createPaymentFromEncryptedDetails(), createPaymentFromToken(),
  • Gravy: createPayment()
  • All perform the same logical operation: authorising a payment

The Solution:
The ApiOperation enum in 1224658 maps all processor-specific method names to a consistent set of canonical operations:

  • authorize - Initial payment authorisation/creation
  • capture - Capture/approve an authorised payment
  • refund - Refund a payment
  • cancel - Cancel/void a payment
  • Plus operations for: getPaymentMethods, getPaymentStatus, getPaymentDetails, createSession, deleteToken, etc.

Benefits:

  1. Cross-processor analysis: Query logs for [*|*|authorize|*] to see all authorization timings regardless of processor
  2. Consistent metrics: Build dashboards using canonical names like "authorize_duration" that work across all processors
  3. Future-proof: Adding new processors just requires mapping their methods to existing canonical operations
  4. Standardised format: All timing logs follow [processor|paymentMethod|operation|request|time] pattern

Example Log Output:

  • Before:
    • [adyen|cc|createPaymentFromEncryptedDetails|request|time]** 1.234567s
    • [gravy|cc|createPayment|request|time] 1.234567s
  • After:
    • [adyen|cc|authorize|request|time] 1.234567s
    • [gravy|cc|authorize|request|time] 1.234567s

Change #1224785 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Structure: Add dLocal api methods to ApiOperations enum

https://gerrit.wikimedia.org/r/1224785

Change #1224792 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Behaviour: Emit ApiTimings for dLocal API calls

https://gerrit.wikimedia.org/r/1224792

Change #1224914 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Add PayPal api methods to ApiOperations enum

https://gerrit.wikimedia.org/r/1224914

Change #1224915 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Emit ApiTimings for PayPal API calls

https://gerrit.wikimedia.org/r/1224915

Change #1224929 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Revert 'Add Gravy SDK wrapper for API timings'

https://gerrit.wikimedia.org/r/1224929

Change #1224938 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Revert 'Add elapsed time to CurlWrapper & Add API call timings to Adyen calls'

https://gerrit.wikimedia.org/r/1224938

Change #1225562 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/SmashPig@master] Derive API timing operation from new #[ApiOp] PHP8 attributes

https://gerrit.wikimedia.org/r/1225562

Change #1224658 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add ApiOperation enum to canonicalise API timing operation names

https://gerrit.wikimedia.org/r/1224658

Change #1219647 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add ApiTimings utility for standardised API timing logs

https://gerrit.wikimedia.org/r/1219647

Change #1220646 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add ApiTimingTrait to standardise API call timing logs

https://gerrit.wikimedia.org/r/1220646

Change #1223718 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Emit ApiTimings for Gravy API calls

https://gerrit.wikimedia.org/r/1223718

Change #1223742 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Emit ApiTimings for Adyen API calls

https://gerrit.wikimedia.org/r/1223742

Change #1224785 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add dLocal api methods to ApiOperations enum

https://gerrit.wikimedia.org/r/1224785

Change #1224792 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Emit ApiTimings for dLocal API calls

https://gerrit.wikimedia.org/r/1224792

Change #1224914 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Add PayPal api methods to ApiOperations enum

https://gerrit.wikimedia.org/r/1224914

Change #1224915 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Emit ApiTimings for PayPal API calls

https://gerrit.wikimedia.org/r/1224915

Change #1224929 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Revert 'Add Gravy SDK wrapper for API timings'

https://gerrit.wikimedia.org/r/1224929

Change #1224938 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Revert 'Add elapsed time to CurlWrapper & Add API call timings to Adyen'

https://gerrit.wikimedia.org/r/1224938

Change #1225562 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Derive API timing operation from new #[ApiOperationAttribute] attribute

https://gerrit.wikimedia.org/r/1225562

We deployed this to the Payments cluster a minute ago, and I can now see structured log data for API timings in the logs:

Jan 28 14:40:41 payments1005 SmashPig-Gravy: gravy::244699877:244699877.1  | (APITimings) [gravy|cc|capture|request|time] 0.828603s |  |
Jan 28 14:40:48 payments1006 SmashPig-Gravy: gravy::244699891:244699891.1  | (APITimings) [gravy|cc|createsession|request|time] 0.171039s |  |
XenoRyet set Final Story Points to 16.