In the event logged on wd_propertysuggester.server_side_property_request, the "request_duration_ms" is -1 in case the request is handled by the PropertySuggester. In cases where it is handled by the SchemaTreeRecommender the time seems correct.
Description
Description
Details
Details
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Open | None | T285098 Production A/B test deployment - Improved Property Suggester/Recommender | |||
| Resolved | BUG REPORT | Martaannaj | T287797 request_duration_ms is -1 in A/B testing when the request goes to the PropertySuggester |
Event Timeline
This comment was removed by Martaannaj.
Comment Actions
@Michaelcochez can you give me an example of an entity where this happens? Because looking at https://wikidata.beta.wmflabs.org/wiki/Q86 (served by the PropertySuggester) the request duration gets logged nicely.
In the implementation, in the case where the call to the SchemaTreeRecommender times out the request gets handled by the PropertySuggester. In these cases the request duration gets logged as -1 to indicate that it was supposed to be handled by the SchemaTreeRecommender but something went wrong with the request so it ended up being executed by the PropertySuggester. Maybe this is what you see in the logs?
I think that what should be seen is one event log where the recommender used is the 'SchemaTreeRecommender' with the request duration of -1 and then another server side log for the same entity but with the recommender used 'PropertySuggester'
Comment Actions
Change 709209 had a related patch set uploaded (by Martaannaj; author: Martaannaj):
[mediawiki/extensions/PropertySuggester@master] Fix setting the request duration correctly for the PropertySuggester
Comment Actions
@Michaelcochez Should be fixed now, in the case where there are no properties already attributed to the entity the PropertySuggester would simply return a pre-set list, so the request duration would be 0 ms. This in turn would cause the line $this->requestDuration ?: -1 to replace the 0 by -1, causing the error.
Comment Actions
The example I was looking at fits the case you describe.
Server
{"meta":{"domain":"wikidata.beta.wmflabs.org","stream":"wd_propertysuggester.server_side_property_request","id":"8c5be2b3-b817-4505-9980-a891db3a5699","dt":"2021-07-30T23:39:01.124Z","request_id":"5147f620-f18f-11eb-8a8c-542020854490"},"http":{"request_headers":{"user-agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.101 Safari/537.36"}},"$schema":"/analytics/mediawiki/wd_propertysuggester/server_side_property_request/1.0.0","propertysuggester_name":"PropertySuggester","existing_properties":[],"existing_types":[],"request_duration_ms":-1,"add_suggestions_made":["694"],"language_code":"en","event_id":"not16276883407032500716a","dt":"2021-07-30T23:39:01Z"}Client
{"$schema":"/analytics/mediawiki/wd_propertysuggester/client_side_property_request/1.0.0","num_characters":1,"user_id":"not logged in","session_id":"YQRsGiDkDtOJKw9uS8U9qQAAABA","entity_id":"Q91","event_id":"not16276878015152500716a","meta":{"stream":"wd_propertysuggester.client_side_property_request","domain":"wikidata.beta.wmflabs.org","id":"4bb6f96d-4b25-464a-9067-7c127fef4764","dt":"2021-07-30T23:30:21.867Z","request_id":"1bc72c60-f18e-11eb-8115-0b14de326e0b"},"dt":"2021-07-30T23:30:01.515Z"}Comment Actions
Change 709209 merged by jenkins-bot:
[mediawiki/extensions/PropertySuggester@master] Fix setting the request duration correctly for the PropertySuggester