Page MenuHomePhabricator

API request time logs should happen after DB commit
Open, Needs TriagePublic

Description

ApiMain::logRequest is called after the API modules' execute actions have finished, but before calling MediaWiki::preOutputCommit. Request timings obtained that way (such as the timeSpentBackend field in ApiAction data) are not really indicative of real processing times.

Event Timeline

Tgr created this task.May 1 2018, 11:29 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMay 1 2018, 11:29 AM
Tgr added a comment.May 1 2018, 11:31 AM

This came up in T193417: ReadingLists performance degradation where the API logs 20-30ms times while RESTBase claims the average request time is multiple seconds. I'm not sure this is the source of the discrepancy but it's the one explanation I can think of.

Anomie added a subscriber: Anomie.May 1 2018, 1:46 PM
In T193484, @Tgr wrote:

Request timings obtained that way (such as the timeSpentBackend field in ApiAction data) are not really indicative of real processing times.

That depends on what exactly you mean by "processing times". The figure currently logged reflects the time spent executing the API module, not including time spend in MediaWiki setup, API setup, or postprocessing.

Having this figure tells you that you should probably be looking at the MediaWiki setup, API setup, or postprocessing (including DB on-commit hooks) rather than the module executions themselves.

Tgr added a comment.May 1 2018, 1:50 PM

I can see how strict module execution times can be useful sometimes but I think most of the time people care about how long responding to an API request takes, and how that's split between module execution, precommit callbacks and other things is a secondary question.

Anomie added a comment.May 1 2018, 2:09 PM

"I think most of the time" is a dangerous phrase. What it really means is "this is what I want now, and I'm projecting that desire".

Nor would simply moving the timing measurement to after the preOutputCommit() call really measure "how long responding to an API request takes", because it still isn't including MediaWiki setup, API setup, output buffer writes, and so on.

Vvjjkkii renamed this task from API request time logs should happen after DB commit to rwdaaaaaaa.Jul 1 2018, 1:12 AM
Vvjjkkii triaged this task as High priority.
Vvjjkkii updated the task description. (Show Details)
Vvjjkkii removed a subscriber: Aklapper.
CommunityTechBot renamed this task from rwdaaaaaaa to API request time logs should happen after DB commit.
CommunityTechBot added a subscriber: Aklapper.
CommunityTechBot raised the priority of this task from High to Needs Triage.Jul 3 2018, 1:54 AM