Page MenuHomePhabricator

Slow query "ApiQueryLogEvents::execute" after actor rollout
Closed, ResolvedPublic

Description

After setting the actor migration to write-both/read-new on group 1, I noticed an increase in slow queries resembling

SELECT /* ApiQueryLogEvents::execute  */  log_id,log_type,log_action,log_timestamp,log_deleted,page_id,log_page,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,user_name,log_namespace,log_title,log_params,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user)) LEFT JOIN `page` ON ((log_namespace=page_namespace) AND (log_title=page_title)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','abusefilterprivatedetails','suppress'))  ORDER BY log_timestamp DESC,log_id DESC LIMIT 501

Event Timeline

Anomie created this task.Apr 15 2019, 3:15 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 15 2019, 3:15 PM

I can't find in the logs which wiki this might be on, so I did an explain on commonswiki as a guess.

wikiadmin@10.64.16.102(commonswiki)> explain SELECT /* ApiQueryLogEvents::execute  */  log_id,log_type,log_action,log_timestamp,log_deleted,page_id,log_page,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,user_name,log_namespace,log_title,log_params,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user)) LEFT JOIN `page` ON ((log_namespace=page_namespace) AND (log_title=page_title)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','abusefilterprivatedetails','suppress'))  ORDER BY log_timestamp DESC,log_id DESC LIMIT 501;
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+
| id   | select_type        | table               | type   | possible_keys                                            | key                   | key_len | ref                                                             | rows    | Extra                           |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+
|    1 | PRIMARY            | actor_log_user      | ALL    | PRIMARY                                                  | NULL                  | NULL    | NULL                                                            | 8158533 | Using temporary; Using filesort |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | commonswiki.actor_log_user.actor_user                           |       1 | Using where                     |
|    1 | PRIMARY            | logging             | ref    | type_time,actor_time,log_actor_type_time,log_type_action | actor_time            | 8       | commonswiki.actor_log_user.actor_id                             |       4 | Using where                     |
|    1 | PRIMARY            | page                | eq_ref | name_title                                               | name_title            | 261     | commonswiki.logging.log_namespace,commonswiki.logging.log_title |       1 | Using index                     |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                  | PRIMARY               | 8       | commonswiki.logging.log_comment_id                              |       1 |                                 |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | change_tag_log_tag_id,change_tag_tag_id_id               | change_tag_log_tag_id | 5       | commonswiki.logging.log_id                                      |       1 | Using index                     |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | commonswiki.change_tag.ct_tag_id                                |       1 |                                 |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+

That's not very good, for some reason it's deciding a full table scan on actor plus a filesort somehow makes sense. This persists even with a much simpler query:

wikiadmin@10.64.16.102(commonswiki)> explain SELECT * FROM logging JOIN actor ON (actor_id = log_actor)  ORDER BY log_timestamp,log_id LIMIT 501;
+------+-------------+---------+------+--------------------------------+------------+---------+----------------------------+---------+---------------------------------+
| id   | select_type | table   | type | possible_keys                  | key        | key_len | ref                        | rows    | Extra                           |
+------+-------------+---------+------+--------------------------------+------------+---------+----------------------------+---------+---------------------------------+
|    1 | SIMPLE      | actor   | ALL  | PRIMARY                        | NULL       | NULL    | NULL                       | 8158537 | Using temporary; Using filesort |
|    1 | SIMPLE      | logging | ref  | actor_time,log_actor_type_time | actor_time | 8       | commonswiki.actor.actor_id |       4 |                                 |
+------+-------------+---------+------+--------------------------------+------------+---------+----------------------------+---------+---------------------------------+

The ideal plan for the simpler query would look more like

wikiadmin@10.64.16.102(commonswiki)> explain SELECT /*!STRAIGHT_JOIN*/ * FROM logging JOIN actor ON (actor_id = log_actor)  ORDER BY log_timestamp,log_id LIMIT 501;
+------+-------------+---------+--------+--------------------------------+---------+---------+-------------------------------+------+-------+
| id   | select_type | table   | type   | possible_keys                  | key     | key_len | ref                           | rows | Extra |
+------+-------------+---------+--------+--------------------------------+---------+---------+-------------------------------+------+-------+
|    1 | SIMPLE      | logging | index  | actor_time,log_actor_type_time | times   | 16      | NULL                          |  501 |       |
|    1 | SIMPLE      | actor   | eq_ref | PRIMARY                        | PRIMARY | 8       | commonswiki.logging.log_actor |    1 |       |
+------+-------------+---------+--------+--------------------------------+---------+---------+-------------------------------+------+-------+

I also tried the query on enwiki (which isn't on read-new yet, but has everything already populated for the switch). It didn't exhibit the problem here:

wikiadmin@10.64.16.101(enwiki)> explain SELECT /* ApiQueryLogEvents::execute  */  log_id,log_type,log_action,log_timestamp,log_deleted,page_id,log_page,actor_log_user.actor_user AS `log_user`,actor_log_user.actor_name AS `log_user_text`,log_actor,user_name,log_namespace,log_title,log_params,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`,(SELECT  GROUP_CONCAT(ctd_name SEPARATOR ',')  FROM `change_tag` JOIN `change_tag_def` ON ((ct_tag_id=ctd_id))   WHERE ct_log_id=log_id  ) AS `ts_tags`  FROM `logging` JOIN `actor` `actor_log_user` ON ((actor_log_user.actor_id = log_actor)) LEFT JOIN `user` ON ((user_id=actor_log_user.actor_user)) LEFT JOIN `page` ON ((log_namespace=page_namespace) AND (log_title=page_title)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','abusefilterprivatedetails','suppress'))  ORDER BY log_timestamp DESC,log_id DESC LIMIT 501;
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-------------------------------------------------------+------+-------------+
| id   | select_type        | table               | type   | possible_keys                                            | key                   | key_len | ref                                                   | rows | Extra       |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-------------------------------------------------------+------+-------------+
|    1 | PRIMARY            | logging             | index  | type_time,actor_time,log_actor_type_time,log_type_action | times                 | 16      | NULL                                                  |  799 | Using where |
|    1 | PRIMARY            | actor_log_user      | eq_ref | PRIMARY                                                  | PRIMARY               | 8       | enwiki.logging.log_actor                              |    1 |             |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | enwiki.actor_log_user.actor_user                      |    1 | Using where |
|    1 | PRIMARY            | page                | eq_ref | name_title                                               | name_title            | 261     | enwiki.logging.log_namespace,enwiki.logging.log_title |    1 | Using index |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                  | PRIMARY               | 8       | enwiki.logging.log_comment_id                         |    1 |             |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | change_tag_log_tag_id,change_tag_tag_id_id               | change_tag_log_tag_id | 5       | enwiki.logging.log_id                                 |   36 | Using index |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | enwiki.change_tag.ct_tag_id                           |    1 |             |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-------------------------------------------------------+------+-------------+

DBAs, any ideas here? Would running an analyze help, do you think?

Marostegui added a subscriber: Marostegui.EditedApr 15 2019, 3:20 PM

A quick check on Tendril for slow queries for ApiQueryLogEvents::execute only gets reports for commonswiki.
I can try to run an analyze table on codfw for the actor table and we can check if that changes the query plan.

So the analyze table for actor table didn't change the pattern:

root@db2073.codfw.wmnet[(none)]> show explain for 6952971;
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+
| id   | select_type        | table               | type   | possible_keys                                            | key                   | key_len | ref                                                             | rows    | Extra                           |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+
|    1 | PRIMARY            | actor_log_user      | ALL    | PRIMARY                                                  | NULL                  | NULL    | NULL                                                            | 8335724 | Using temporary; Using filesort |
|    1 | PRIMARY            | user                | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | commonswiki.actor_log_user.actor_user                           |       1 | Using where                     |
|    1 | PRIMARY            | logging             | ref    | type_time,actor_time,log_actor_type_time,log_type_action | log_actor_type_time   | 8       | commonswiki.actor_log_user.actor_id                             |       3 | Using index condition           |
|    1 | PRIMARY            | page                | eq_ref | name_title                                               | name_title            | 261     | commonswiki.logging.log_namespace,commonswiki.logging.log_title |       1 | Using index                     |
|    1 | PRIMARY            | comment_log_comment | eq_ref | PRIMARY                                                  | PRIMARY               | 8       | commonswiki.logging.log_comment_id                              |       1 |                                 |
|    2 | DEPENDENT SUBQUERY | change_tag          | ref    | change_tag_log_tag_id,change_tag_tag_id_id               | change_tag_log_tag_id | 5       | commonswiki.logging.log_id                                      |       1 | Using index                     |
|    2 | DEPENDENT SUBQUERY | change_tag_def      | eq_ref | PRIMARY                                                  | PRIMARY               | 4       | commonswiki.change_tag.ct_tag_id                                |       1 |                                 |
+------+--------------------+---------------------+--------+----------------------------------------------------------+-----------------------+---------+-----------------------------------------------------------------+---------+---------------------------------+
7 rows in set, 1 warning (0.04 sec)

There is also the fact that the logging table uses a different index.
On commons it chooses log_actor_type_time whereas on enwiki it uses times (might or might not be relevant). Both hosts I have tested on are on 10.1.37.

I think the different index choice is a side effect of it choosing to scan actor first instead of logging.

A count on commonswiki is: 8335746
On enwiki it is way larger: 82373996

Maybe it is the optimizer being stupid again assuming that it is faster to do a full scan than actually going thru the index. Not the first time we have seen that on a same table, but with such big difference in rows between wikis.

I ran explain SELECT * FROM logging JOIN actor ON (actor_id = log_actor) ORDER BY log_timestamp,log_id LIMIT 501 on all wikis (a random 'api'-group host, or a random general host for s3) and found three patterns: the good plan, the bad plan, and a plan that does a full scan of logging that probably corresponds to wikis with very few logging rows. It does seem to correlate with the count of actor rows.

wikiplan# actors# log entriesactor/log ratio
fixcopyrightwikibad71890.0370
romdwikimediabad7220.3182
ilwikimediabad262240.1161
ombudsmenwikibad473750.1253
kwwikiquotebad33123410.1414
biwikibooksbad36322630.1604
gotwikibooksbad36522870.1596
bmwikibooksbad37623530.1598
rmwikibooksbad38322960.1668
gnwikibooksbad41023860.1718
gawikibooksbad41222190.1857
bmwikiquotebad41423560.1757
pmswikisourcebad42343840.0965
idwikimediagood427548000.0078
sahwikiquotebad42912070.3554
piwiktionarybad43123310.1849
avwiktionarybad48621900.2219
euwikisourcebad53826720.2013
pswikivoyagebad54511900.4580
swwikibooksbad55925040.2232
ndswikibooksbad57322830.2510
abwiktionarybad57423720.2420
aswiktionarybad57523080.2491
hifwiktionarybad58220220.2878
nawikibooksbad59325390.2336
zuwikibooksbad65025860.2514
mnwikibooksbad67226230.2562
aawikibooksbad67844130.1536
sdwikinewsbad75523730.3182
zh_min_nanwikiquotebad78844660.1764
bawikibooksbad82550860.1622
angwikiquotebad87023890.3642
zawiktionarybad87795220.0921
amwikiquotebad97330670.3172
uzwikibooksbad98430240.3254
ikwiktionarybad113633450.3396
kjwikibad119929090.4122
iewikibooksbad126234900.3616
gorwikibad129467810.1908
pnbwiktionarybad136054650.2489
wowikiquotebad140236770.3813
sawikiquotebad148236890.4017
mgwikibooksbad153937150.4143
iiwikibad166599810.1668
tnwiktionarybad177141370.4281
tswiktionarybad182643040.4243
aswikisourcebad198769350.2865
euwikibooksbad198742910.4631
zh_min_nanwikisourcebad200555540.3610
pawiktionarybad209174910.2791
roa_rupwiktionarybad214057630.3713
brwikisourcebad218771340.3066
vecwiktionarybad221364410.3436
pswiktionarybad225274310.3031
nawiktionarybad228053130.4291
jbowiktionarybad228350990.4477
iswikiquotebad248260180.4124
sqwikiquotebad263067540.3894
gdwiktionarybad270065490.4123
jvwiktionarybad2764151870.1820
bgwikinewsbad312275880.4114
miwiktionarybad313876630.4095
ndswiktionarybad3295125550.2624
cowiktionarybad339388670.3827
wawiktionarybad3430435220.0788
urwiktionarybad3966162360.2443
astwiktionarybad4003139420.2871
liwiktionarygood4086360270.1134
iawiktionarybad4154117500.3535
ocwiktionarybad4293135190.3176
bgwikisourcebad4615856210.0539
lrcwikibad4626152620.3031
sewikimediabad4710110630.4257
foundationwikibad5059283040.1787
nowikisourcebad5064130150.3891
testwikidatawikibad5193706510.0735
srwikiquotebad5341147830.3613
bgwikibooksgood5496614610.0894
skwiktionarybad5558138990.3999
tawikinewsbad5638223820.2519
sawikisourcegood6068315710.1922
cawikinewsgood66551226620.0543
fawikinewsgood71222153210.0331
srwikinewsgood71244416240.0161
mlwiktionarygood7659261430.2930
iswiktionarygood79621401250.0568
azwikisourcebad8151195880.4161
iowiktionarygood8374879050.0953
mgwiktionarybad858816638200.0052
hywiktionarygood9209574260.1604
etwiktionarybad9333272700.3422
hywikisourcebad9430322850.2921
srwiktionarybad9918832650.1191
ukwikisourcebad10285242550.4240
bnwikisourcegood11287679120.1662
ltwiktionarygood11729432970.2709
hiwiktionarygood117631046810.1124
mlwikisourcegood11960470160.2544
svwikisourcebad12358339670.3638
roa_rupwikigood12864811430.1585
bgwikiquotegood13072931100.1404
srwikisourcebad13529410270.3298
cbk_zamwikibad13584307240.4421
thwiktionarygood13700446830.3066
sdwikigood13702391550.3499
huwikibooksgood14034668130.2100
kowikisourcegood14297360820.3962
cswikisourcegood14403498810.2887
labswikigood151584536780.0334
nowiktionarygood16583273420.6065
viwikibooksbad17634462080.3816
tawiktionarygood17843358460.4978
rowiktionarygood18020296680.6074
cawiktionarygood18617772150.2411
plwikinewsgood20741922460.2248
kshwikigood209965515580.0381
ukwiktionarygood214741276330.1682
yowikigood22475397050.5660
arwikinewsgood22882354900.6447
kowiktionarybad22990570640.4029
newwikigood23058520660.4429
diqwikibad23252631460.3682
pswikigood24085483810.4978
cewikibad2410026816170.0090
azbwikigood252492100070.1202
pmswikigood25621334570.7658
mgwikibad25659724330.3542
huwiktionarygood26749538490.4967
bgwiktionarygood267571397530.1915
aswikigood27628424530.6508
ptwikinewsgood281322837060.0992
zhwikinewsgood28380552730.5135
test2wikigood285751557670.1834
idwiktionarygood28783571730.5034
orwikigood29483500170.5895
napwikigood30156649840.4641
hewikisourcegood307611106790.2779
hewikibooksgood30894403870.7649
kywikigood31308562140.5569
vecwikigood315531218770.2589
itwikivoyagegood319831415390.2260
bawikigood32115793560.4047
lmowikigood328741620890.2028
arwiktionarygood328961692460.1944
ruwikiversitygood32906415700.7916
itwikinewsgood33084838450.3946
plwikisourcegood3342922175310.0151
sawikigood33575510130.6582
tgwikigood33749978920.3448
kmwikigood34286520850.6583
ruwikivoyagegood34568984930.3510
outreachwikigood34638602900.5745
idwikibooksgood35103461060.7614
sowikigood35525405360.8764
simplewiktionarygood35621620020.5745
pawikigood35987649900.5537
ptwikiversitygood36247488320.7423
amwikigood36562413550.8841
ptwikisourcegood371253365020.1103
itwikiversitygood40148756650.5306
arwikibooksgood40189493000.8152
fiwiktionarygood408471449050.2819
ttwikibad41233979420.4210
hewiktionarygood41692478780.8708
yiwikigood42495573040.7416
ckbwikibad436921030440.4240
dewikiversitygood43731855790.5110
fywikibad437531039630.4209
viwiktionarygood44062542330.8125
scnwikigood44129537510.8210
trwikiquotegood44187857980.5150
nlwikibooksgood442301340650.3299
eswikinewsgood446605094910.0877
dewikinewsgood44828824070.5440
cswiktionarygood45081921960.4890
plwikibooksgood45096926480.4867
ptwikiquotegood45101616520.7315
iawikibad451871296850.3484
swwikigood46521692430.6719
warwikigood46795617540.7578
frwikinewsgood469615978160.0786
brwikimediagood47294507250.9324
ruwikinewsgood474575259110.0902
zh_min_nanwikigood47810905140.5282
zhwikiquotegood47914556750.8606
betawikiversitygood49234750720.6558
arwikisourcegood50759883850.5743
jvwikigood51650831230.6214
ndswikigood519311039980.4993
nlwiktionarygood520691186060.4390
gawikigood52437600390.8734
ocwikigood52599847690.6205
siwikigood54664728500.7504
zhwikibooksgood55424717900.7720
kuwikigood56020775540.7223
testwikigood567741636280.3470
uzwikibad573421338860.4283
jawikibooksgood57412617540.9297
newikigood58752823580.7134
barwikigood59215955770.6196
itwikisourcegood593043138800.1889
eswikiversitygood60202755750.7966
frwikivoyagegood61558801960.7676
bhwikigood62209631280.9854
svwiktionarybad623021579220.3945
itwikibooksgood638761404020.4550
anwikigood65165875240.7445
lbwikigood657311135120.5791
elwiktionarygood65931888680.7419
cebwikibad664763808810.1745
wuuwikigood66873981900.6811
mywikigood671191092580.6143
frwikiquotegood71375848700.8410
brwikigood71598878180.8153
trwiktionarygood722811447800.4992
jawiktionarygood723451049730.6892
ruwikibooksgood74257782780.9486
scowikigood750241009520.7432
dewikivoyagegood754431581460.4770
mnwikigood76174995700.7650
cywikigood761831177600.6469
dewikisourcegood783825084520.1542
ptwikibooksgood789901587740.4975
astwikigood792581278700.6198
plwikiquotegood804721967560.4090
zhwikisourcegood807792753440.2934
be_x_oldwikigood813911309200.6217
frwikiversitygood823082405720.3421
guwikigood83493877150.9519
zh_classicalwikigood850191241930.6846
zhwiktionarygood875781782040.4914
alswikigood879827586820.1160
eswikisourcegood881081275670.6907
knwikigood926961103760.8398
dewikiquotegood95353960510.9927
ruwikisourcegood9943934556440.0288
iswikigood1017771217330.8361
plwiktionarygood10208142972730.0238
angwikigood1036771063260.9751
itwiktionarygood1056532134390.4950
kkwikigood1091582613530.4177
ptwiktionarygood1103451525500.7233
bewikigood11655123273650.0501
urwikigood1189522604140.4568
ruwikiquotegood11983534016660.0352
frwikisourcegood12588128892950.0436
mkwikigood12955128277330.0458
frwikibooksgood1326472005640.6614
eswikiquotegood1340361058031.2668
hywikigood1340853626960.3697
mrwikigood1354551886510.7180
tewikigood1368051821820.7509
afwikigood1393122902290.4800
itwikiquotegood1399142704910.5173
nnwikigood1425942724310.5234
arzwikigood1426432088630.6830
eswikibooksgood1430591520610.9408
lvwikigood1432982829720.5064
kawikigood15847316341020.0970
lawikigood1638411840660.8901
euwikigood1647484651920.3542
eswiktionarygood1655962444720.6774
sqwikigood1665737660100.2175
glwikigood1667222694680.6187
tlwikigood1670731911020.8743
dewikibooksgood1708182245830.7606
bswikigood18334213260900.1383
shwikigood1958742939450.6664
tawikigood2130493566720.5973
zh_yuewikigood2164392288040.9460
etwikigood2244303093110.7256
eowikibad23341227152020.0860
mlwikigood2378954048150.5877
sourceswikigood2528193717670.6800
azwikigood2545426360200.4002
dewiktionarygood26555856507330.0470
bnwikigood2729655096290.5356
ltwikigood2746583643670.7538
slwikigood2898783511430.8255
ruwiktionarygood31661939034960.0811
skwikigood3425154514340.7587
mswikigood3602544878020.7385
frwiktionarygood43646313084200.3336
hrwikigood44156615834960.2789
srwikigood47264522960810.2058
bgwikigood54169214793880.3662
hiwikigood5885309923380.5931
elwikigood6285766699370.9383
cawikigood66316478876490.0841
dawikigood67794318025220.3761
rowikigood78776513426200.5867
thwikigood8089329399030.8607
huwikibad839094117262730.0716
cswikigood84647515645060.5410
ukwikigood89907995149950.0945
nowikibad95289666649130.1430
viwikibad106938228697160.3726
fiwikibad108956071442930.1525
kowikigood117760818138870.6492
simplewikigood119163512661970.9411
fawikigood136415435857620.3804
hewikigood137945136479630.3781
idwikibad146456067705040.2163
svwikigood163665622792360.7181
enwikivoyagegood251555425048291.0043
incubatorwikigood256240828959560.8848
trwikigood257140788157830.2917
nlwikigood2584582123136140.2099
arwikibad2843843198154190.1435
enwikinewsgood285407935346590.8075
specieswikigood285690831731410.9003
plwikigood2888586334175950.0864
enwikiversitygood292576531116310.9403
enwikisourcegood294469039079290.7535
enwikiquotegood333235631634771.0534
enwikibooksgood353531244514250.7942
wikidatawikigood398363273059400.5453
enwiktionarygood412229068301090.6035
zhwikigood474087059419880.7979
jawikigood507037738420831.3197
ptwikigood6395025156523270.4086
itwikigood671113280398690.8347
ruwikibad6874186560021890.1227
commonswikibad8335862868261820.0960
frwikigood9666035167895430.5757
dewikigood13476346921221790.1463
eswikigood1505451397824761.5389
mediawikiwikigood17291684178580350.9683
metawikigood23676259254287960.9311
loginwikigood23856952239013010.9981
enwikigood82374692809170851.0180

I guess we need to FORCE index? :(

We could force a STRAIGHT_JOIN instead. I'm not sure which would be better.

STRAIGHT_JOIN could be validly applied for almost all the code paths,[1] while the index forcing would need to be specific to the code path generating this query as other paths target other indexes. On the other hand, perhaps specifically targeting the one code path is exactly what we should do.

Ok, looking at slow query logs for yesterday and today, I see 1600 that look like the code path for the query in the description, and 96 for a different code path that would need a different index forced. It's possible that other code paths would also run into this bug and just haven't been executed yet. So we'd probably want to add the index forcing to almost all the code paths, just to be safe.

[1]: There's one exception, that depends heavily on the details of the rows that would match each way.

If you want a practical (but general) reason of STRAIGHT_JOIN vs FORCE, I would vote for STRAIGHT_JOIN (both can create bad query plans, but S_J cannot create a hard fail. I have no opinion for this particular case, though.

Change 504391 had a related patch set uploaded (by Anomie; owner: Anomie):
[mediawiki/core@master] API: Add STRAIGHT_JOIN to ApiQueryLogEvents to avoid MySQL planner oddness

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

Marostegui triaged this task as Normal priority.Apr 18 2019, 6:31 PM
Marostegui moved this task from Triage to In progress on the DBA board.

Change 504391 merged by jenkins-bot:
[mediawiki/core@master] Add STRAIGHT_JOIN to ApiQueryLogEvents and LogPager to avoid planner oddness

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

Anomie moved this task from Done to Pending deploy on the MediaWiki-API board.Apr 26 2019, 6:39 PM
Marostegui assigned this task to Anomie.May 6 2019, 5:26 AM

Closing this as resolved as this patch fixed it (same as T221511#5153193). There are also no more reports on Tendril

Marostegui closed this task as Resolved.May 6 2019, 5:26 AM