🐛 Performance report: SQL Query took x ms:

[CatsEyeXI]

I affirm:

• I understand that if I do not agree to the following points by completing the checkboxes my issue will be ignored.
• I have read and understood the Contributing Guide and the Code of Conduct.
• I have searched existing issues to see if the issue has already been opened, and I have checked the commit log to see if the issue has been resolved since my server was last updated.

OS / platform the server is running (if known)

Windows10

Branch affected by issue

base

Steps to reproduce

Scraped map server logs for "SQL query took". Wanted to share here in case there was anything that could be improved on, or shed some light on a potential issue.

Map servers and MariaDB are on the same box communicating over loopback address.

SQL query took 2881ms: INSERT INTO char_equip SET charid = 12063, equipslotid = 10 , slotid  = 19, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 19, containerid = 8;
SQL query took 107ms: INSERT INTO char_equip SET charid = 12063, equipslotid = 11 , slotid  = 60, containerid = 10 ON DUPLICATE KEY UPDATE slotid  = 60, containerid = 10;
[map][warn] SQL query took 133ms: UPDATE char_look SET head = 20, body = 129, hands = 21, legs = 88, feet = 6, main = 265, sub = 36, ranged = 0 WHERE charid = 14338; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 243ms: UPDATE chars SET isstylelocked = 0 WHERE charid = 14338; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 148ms: INSERT INTO char_equip SET charid = 14338, equipslotid = 8 , slotid  = 22, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 22, containerid = 8; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 123ms: UPDATE chars SET pos_zone = 103,pos_prevzone = 245,pos_rot = 0,pos_x = 128.163,pos_y = -7.320,pos_z = 95.083,moghouse = 0,boundary = 0 WHERE charid = 2161; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 130ms: DELETE FROM char_equip WHERE charid = 14338 AND  equipslotid = 0 LIMIT 1; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 122ms: INSERT INTO char_equip SET charid = 14338, equipslotid = 3 , slotid  = 24, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 24, containerid = 8; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 152ms: INSERT INTO char_equip SET charid = 14338, equipslotid = 4 , slotid  = 5, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 5, containerid = 8; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 106ms: INSERT INTO char_equip SET charid = 14338, equipslotid = 6 , slotid  = 9, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 9, containerid = 8; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 148ms: INSERT INTO char_equip SET charid = 14338, equipslotid = 9 , slotid  = 4, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 4, containerid = 8; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 115ms: INSERT INTO char_equip SET charid = 1445, equipslotid = 7 , slotid  = 61, containerid = 10 ON DUPLICATE KEY UPDATE slotid  = 61, containerid = 10; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 130ms: INSERT INTO char_equip SET charid = 1445, equipslotid = 10 , slotid  = 58, containerid = 12 ON DUPLICATE KEY UPDATE slotid  = 58, containerid = 12; (SqlConnection::QueryStr:352)
[map][warn] SQL query took 158ms: DELETE FROM char_equip WHERE charid = 1499 AND  equipslotid = 17 LIMIT 1; (SqlConnection::QueryStr:352)
[map][error] SQL query took 422ms: UPDATE char_look SET head = 93, body = 185, hands = 185, legs = 185, feet = 185, main = 442, sub = 0, ranged = 0 WHERE charid = 1499; (SqlConnection::QueryStr:348)
SQL query took 266ms: INSERT INTO char_inventory(charid,location,slot,itemId,quantity,signature,extra) VALUES(15177,0,33,4181,1,'','\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0')
SQL query took 249ms: SELECT zoneip, zoneport FROM zone_settings WHERE zoneid = 245;
SQL query took 106ms: UPDATE accounts_sessions SET server_addr = 4096519264, server_port = 54334 WHERE charid = 14338;
SQL query took 142ms: UPDATE chars SET pos_zone = 245,pos_prevzone = 230,pos_rot = 0,pos_x = 0.000,pos_y = 0.000,pos_z = 0.000,moghouse = 0,boundary = 0 WHERE charid = 14338;
SQL query took 143ms: SELECT partyid, allianceid, partyflag & 3 FROM accounts_sessions s JOIN accounts_parties p ON s.charid = p.charid WHERE p.charid = 14338;
SQL query took 364ms: SELECT zoneip, zoneport FROM zone_settings WHERE zoneid = 267;
SQL query took 245ms: UPDATE char_inventory SET quantity = 15981157 WHERE charid = 10533 AND location = 0 AND slot = 0;
SQL query took 114ms: SELECT zoneip, zoneport FROM zone_settings WHERE zoneid = 232;
SQL query took 655ms: UPDATE accounts_sessions SET server_addr = 4096519264, server_port = 54332 WHERE charid = 10533;
SQL query took 242ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 3 , slotid  = 60, containerid = 12 ON DUPLICATE KEY UPDATE slotid  = 60, containerid = 12;
SQL query took 131ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 4 , slotid  = 18, containerid = 14 ON DUPLICATE KEY UPDATE slotid  = 18, containerid = 14;
SQL query took 109ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 5 , slotid  = 21, containerid = 13 ON DUPLICATE KEY UPDATE slotid  = 21, containerid = 13;
SQL query took 127ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 14 , slotid  = 69, containerid = 11 ON DUPLICATE KEY UPDATE slotid  = 69, containerid = 11;
SQL query took 131ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 15 , slotid  = 47, containerid = 12 ON DUPLICATE KEY UPDATE slotid  = 47, containerid = 12;
SQL query took 128ms: INSERT INTO char_equip SET charid = 1499, equipslotid = 16 , slotid  = 44, containerid = 7 ON DUPLICATE KEY UPDATE slotid  = 44, containerid = 7;
SQL query took 105ms: DELETE FROM char_equip WHERE charid = 1499 AND  equipslotid = 17 LIMIT 1;
SQL query took 113ms: UPDATE char_look SET head = 93, body = 185, hands = 185, legs = 185, feet = 185, main = 442, sub = 0, ranged = 0 WHERE charid = 1499;
SQL query took 210ms: UPDATE chars SET isstylelocked = 1 WHERE charid = 1499;
SQL query took 133ms: UPDATE char_stats SET zoning = 1 WHERE charid = 11366
SQL query took 165ms: SELECT charid FROM chars WHERE charid = 14338 LIMIT 1;
SQL query took 114ms: SELECT charname,pos_zone,pos_prevzone,pos_rot,pos_x,pos_y,pos_z,moghouse,boundary,home_zone,home_rot,home_x,home_y,home_z,nation,quests,keyitems,abilities,weaponskills,titles,zones,missions,assault,campaign,eminence,playtime,campaign_allegiance,isstylelocked,moghancement,UNIX_TIMESTAMP(`lastupdate`),languages,chatfilters FROM chars WHERE charid = 14338
SQL query took 177ms: SELECT char_spells.spellid FROM char_spells JOIN spell_list ON spell_list.spellid = char_spells.spellid WHERE charid = 14338 AND (spell_list.content_tag IN ("","COP","TOAU","WOTG","ACP","AMK","ASA","ABYSSEA","SOA","ROV") OR spell_list.content_tag IS NULL);
SQL query took 192ms: SELECT mode, war, mnk, whm, blm, rdm, thf, pld, drk, bst, brd, rng, sam, nin, drg, smn, blu, cor, pup, dnc, sch, geo, run, merits, limits FROM char_exp WHERE charid = 14338;
SQL query took 114ms: SELECT nameflags, mjob, sjob, hp, mp, mhflag, title, bazaar_message, zoning, pet_id, pet_type, pet_hp, pet_mp, pet_level FROM char_stats WHERE charid = 14338;
SQL query took 116ms: UPDATE char_stats SET zoning = 0 WHERE charid = 14338
SQL query took 178ms: SELECT itemid,location,slot,quantity,bazaar,signature, extra FROM char_inventory WHERE charid = 14338 ORDER BY FIELD(location,0,1,9,2,3,4,5,6,7,8,10,11,12)
SQL query took 336ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 514
SQL query took 376ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 517
SQL query took 771ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 516
SQL query took 129ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 518
SQL query took 107ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 518
SQL query took 105ms: SELECT augmentId, multiplier, modId, `value`, `isPet`, `petType` FROM augments WHERE augmentId = 517
SQL query took 2934ms: REPLACE INTO char_recast VALUES (14338, 0, 1696260483, 0);
[10/02/23 11:27:46:450][map][warn] SQL query took 143ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16368 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:352)
[10/02/23 11:27:47:637][map][warn] SQL query took 123ms: SELECT session_key FROM accounts_sessions WHERE charid = 16242 LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:27:47:789][map][warn] SQL query took 151ms: SELECT charname,pos_zone,pos_prevzone,pos_rot,pos_x,pos_y,pos_z,moghouse,boundary,home_zone,home_rot,home_x,home_y,home_z,nation,quests,keyitems,abilities,weaponskills,titles,zones,missions,assault,campaign,eminence,playtime,campaign_allegiance,isstylelocked,moghancement,UNIX_TIMESTAMP(`lastupdate`),languages,chatfilters FROM chars WHERE charid = 16242 (SqlConnection::QueryStr:352)
[10/02/23 11:27:47:969][map][warn] SQL query took 106ms: SELECT rank_points,rank_sandoria,rank_bastok,rank_windurst,fame_sandoria,fame_bastok,fame_windurst,fame_norg, fame_jeuno, fame_aby_konschtat, fame_aby_tahrongi, fame_aby_latheine, fame_aby_misareaux, fame_aby_vunkerl, fame_aby_attohwa, fame_aby_altepa, fame_aby_grauberg, fame_aby_uleguerand, fame_adoulin,unity_leader FROM char_profile WHERE charid = 16242; (SqlConnection::QueryStr:352)
[10/02/23 11:27:51:160][map][warn] SQL query took 205ms: SELECT login_points FROM char_points WHERE charid = 16242; (SqlConnection::QueryStr:352)
[10/02/23 11:27:51:453][map][error] SQL query took 292ms: SELECT value, expiry FROM char_vars WHERE charid = 16242 AND varname = 'LoginCampaignMonth' LIMIT 1; (SqlConnection::QueryStr:348)
[10/02/23 11:27:51:672][map][warn] SQL query took 219ms: SELECT value, expiry FROM char_vars WHERE charid = 16242 AND varname = 'LoginCampaignYear' LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:27:51:958][map][error] SQL query took 284ms: INSERT INTO char_vars SET charid = 16242, varname = 'LoginCampaignNextMidnight', value = 1696345200, expiry = 0 ON DUPLICATE KEY UPDATE value = 1696345200, expiry = 0; (SqlConnection::QueryStr:348)
[10/02/23 11:27:52:138][map][warn] SQL query took 178ms: UPDATE char_points SET login_points = GREATEST(LEAST(login_points+200, 2147483647), 0) WHERE charid = 16242; (SqlConnection::QueryStr:352)
[10/02/23 11:27:52:504][map][error] SQL query took 277ms: INSERT INTO char_vars SET charid = 16242, varname = 'LoginCampaignLoginNumber', value = 3, expiry = 0 ON DUPLICATE KEY UPDATE value = 3, expiry = 0; (SqlConnection::QueryStr:348)
[10/02/23 11:28:00:119][map][warn] SQL query took 229ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16484 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:352)
[10/02/23 11:28:04:000][map][error] SQL query took 391ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16368 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:348)
[10/02/23 11:28:08:253][map][warn] SQL query took 190ms: UPDATE char_inventory SET quantity = 12 WHERE charid = 13785 AND location = 0 AND slot = 13; (SqlConnection::QueryStr:352)
[10/02/23 11:28:09:012][map][warn] SQL query took 196ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16484 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:352)
[10/02/23 11:28:09:650][map][warn] SQL query took 158ms: INSERT INTO char_vars SET charid = 16076, varname = '[regime]killed1', value = 3, expiry = 0 ON DUPLICATE KEY UPDATE value = 3, expiry = 0; (SqlConnection::QueryStr:352)
[10/02/23 11:28:09:953][map][warn] SQL query took 111ms: DELETE FROM char_vars WHERE charid = 16076 AND varname = 'jugpet-duration-seconds' LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:28:10:178][map][warn] SQL query took 199ms: DELETE FROM char_vars WHERE charid = 16368 AND varname = 'jugpet-spawn-time' LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:28:10:411][map][warn] SQL query took 209ms: DELETE FROM char_vars WHERE charid = 15737 AND varname = 'jugpet-duration-seconds' LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:28:10:549][map][warn] SQL query took 137ms: UPDATE char_stats SET hp = 213, mp = 110, nameflags = 73728, mhflag = 15, mjob = 15, sjob = 3, pet_id = 8, pet_type = 0, pet_hp = 0, pet_mp = 0, pet_level = 0 WHERE charid = 14176; (SqlConnection::QueryStr:352)
Binary file Zones_6.txt matches
[10/02/23 11:27:46:154][map][warn] SQL query took 108ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16202 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:352)
[10/02/23 11:27:54:989][map][warn] SQL query took 149ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 0 , slotid  = 60, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 60, containerid = 8; (SqlConnection::QueryStr:352)
[10/02/23 11:27:55:098][map][warn] SQL query took 109ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 1 , slotid  = 55, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 55, containerid = 8; (SqlConnection::QueryStr:352)
[10/02/23 11:27:55:213][map][warn] SQL query took 114ms: DELETE FROM char_equip WHERE charid = 16202 AND  equipslotid = 2 LIMIT 1; (SqlConnection::QueryStr:352)
[10/02/23 11:27:55:399][map][warn] SQL query took 185ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 3 , slotid  = 56, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 56, containerid = 8; (SqlConnection::QueryStr:352)
[10/02/23 11:27:55:514][map][warn] SQL query took 114ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 4 , slotid  = 61, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 61, containerid = 8; (SqlConnection::QueryStr:352)
[10/02/23 11:27:58:669][map][error] SQL query took 451ms: UPDATE char_inventory SET quantity = 7 WHERE charid = 13796 AND location = 0 AND slot = 32; (SqlConnection::QueryStr:348)
[10/02/23 11:27:58:812][map][warn] SQL query took 142ms: DELETE FROM char_inventory WHERE charid = 13796 AND location = 0 AND slot = 34; (SqlConnection::QueryStr:352)
[10/02/23 11:28:01:227][map][error] SQL query took 382ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 0 , slotid  = 60, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 60, containerid = 8; (SqlConnection::QueryStr:348)
[10/02/23 11:28:01:724][map][error] SQL query took 497ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 1 , slotid  = 55, containerid = 8 ON DUPLICATE KEY UPDATE slotid  = 55, containerid = 8; (SqlConnection::QueryStr:348)
[10/02/23 11:28:02:088][map][error] SQL query took 341ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 5 , slotid  = 8, containerid = 10 ON DUPLICATE KEY UPDATE slotid  = 8, containerid = 10; (SqlConnection::QueryStr:348)
[10/02/23 11:28:02:636][map][warn] SQL query took 102ms: INSERT INTO char_equip SET charid = 16202, equipslotid = 16 , slotid  = 1, containerid = 7 ON DUPLICATE KEY UPDATE slotid  = 1, containerid = 7; (SqlConnection::QueryStr:352)
[10/02/23 11:28:02:861][map][warn] SQL query took 216ms: UPDATE char_look SET head = 0, body = 35, hands = 96, legs = 74, feet = 74, main = 354, sub = 176, ranged = 0 WHERE charid = 16202; (SqlConnection::QueryStr:352)
[10/02/23 11:28:09:172][map][warn] SQL query took 203ms: SELECT chars.charid, partyid, allianceid, charname, partyflag, pos_zone, pos_prevzone FROM accounts_parties                                     LEFT JOIN chars ON accounts_parties.charid = chars.charid WHERE                                     (allianceid <> 0 AND allianceid = 0) OR partyid = 16202 ORDER BY partyflag & 3, timestamp; (SqlConnection::QueryStr:352)

Expected behavior

Not sure if these warnings are something to be concerned about.

[TeoTwawki]

personally I feel anything below 150ms is essentially nothing. and anything approaching 400ms is an utter disaster (ticks are 400ms each, shit needs to be over with before next tick).

Current thresholds are 100 for warn and 250 for error (error to show they are more serious - def give us those).

I noted the worst offenders were involving key lookups and UPDATE statements (and ON DUPLICATE KEY UPDATE combines both, sometimes spiking to over 550ms)

If they get to noisy for you you can adjust the logging settings. There is an on/off and a setting for each threshold. I've adjusted my error from 250 to 300 on my testbed and I am actively looking at how to make sure all queries come in under 300. We want to trend them lower over time and there are some longer term plans for this that we've no current ETA for.

[zach2good]

Thanks for reporting!

This does confirm some suspicions Teo had about the cost of ON DUPLICATE KEY UPDATE , REPLACE INTO, and queries on large char tables.

We've started planning out some stored proc work that should bring down the timings for all queries, but it's not even in the prototyping stages yet.

Like Teo says, if it's too noisy for you you can jack up the numbers in the settings, but like the watchdog timer, these are there to warn on things that are quite important.

[zach2good]

Is this still an issue after the SQL refactor? (I don't know if these specific queries were captured in that rewrite)