Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

MediaWiki profiling output interpretation

I have a MediaWiki Installation for logged in users only which is very slow (about constantly 2.5 seconds per request) I went through all steps of caching and optimization i have found. I use APC with default configuration and since i have not found any improvements i ran the mediawiki profiling, but i don't fully unserstand the output.

The output from the forceprofile looks like the following.

100.00% 2.475774      1 - -total
 90.51% 2.240709      1 - Setup.php
 89.56% 2.217199      1 - Setup.php-session
 88.85% 2.199760    163 - LoadBalancer::getConnection
 88.64% 2.194557    163 - LoadBalancer::openConnection
 88.43% 2.189371      2 - DatabaseMysql::open
 88.38% 2.188186      2 - dbconnect-localhost
  8.02% 0.198664      1 - MediaWiki::main
  6.15% 0.152351      1 - MediaWiki::finalCleanup
  5.25% 0.129948      1 - OutputPage::output
  5.21% 0.128936      1 - Output-skin
  5.20% 0.128861      1 - SkinTemplate::outputPage
  3.28% 0.081173    186 - DatabaseBase::query
  2.64% 0.065307      1 - SkinTemplate::outputPage-stuff5
  1.99% 0.049177      4 - query: COMMIT
  1.82% 0.044994      1 - MediaWiki::performRequest
  1.67% 0.041237      1 - MediaWiki::performAction
  1.66% 0.041093      1 - Article::view
  1.56% 0.038637    108 - LocalisationCache::getSubitem-load
  1.41% 0.034958      1 - SkinTemplate::outputPage-execute
  1.09% 0.026959      1 - Skin::buildSidebar
  1.04% 0.025770     41 - Linker::titleAttrib
  rest below 1%

the output in the profiling log looks:

    Profiling data
    Name                                                                         Calls         Total          Each             %       Mem
    -total                                                                           1      2530.972      2530.972       100.000%   5801152  (     2530.972 -     2530.972) [0]
    Setup.php                                                                        1      2269.201      2269.201        89.657%   1230737  (     2269.201 -     2269.201) [65]
    Setup.php-session                                                                1      2246.935      2246.935        88.778%    312683  (     2246.935 -     2246.935) [26]
    LoadBalancer::getConnection                                                    166      2213.220        13.333        87.445%    292024  (        0.005 -     1117.286) [178]
    LoadBalancer::openConnection                                                   166      2211.142        13.320        87.363%    286279  (        0.001 -     1117.276) [12]
    DatabaseMysql::open                                                              2      2208.200      1104.100        87.247%     13050  (     1092.796 -     1115.404) [10]
    dbconnect-localhost                                                              2      2207.259      1103.630        87.210%     12544  (     1092.338 -     1114.922) [0]
    MediaWiki::main                                                                  1       222.392       222.392         8.787%   2675660  (      222.392 -      222.392) [1486]
    MediaWiki::finalCleanup                                                          1       134.699       134.699         5.322%   1284487  (      134.699 -      134.699) [981]
    DatabaseBase::query                                                            202       117.272         0.581         4.633%    342809  (        0.079 -       32.658) [206]
    OutputPage::output                                                               1       108.740       108.740         4.296%   1280174  (      108.740 -      108.740) [956]
    Output-skin                                                                      1       103.328       103.328         4.083%   1087262  (      103.328 -      103.328) [953]
    SkinTemplate::outputPage                                                         1       103.267       103.267         4.080%   1131051  (      103.267 -      103.267) [952]
    query: COMMIT                                                                    7        87.476        12.497         3.456%       432  (        6.541 -       32.651) [0]
    MediaWiki::performRequest                                                        1        85.917        85.917         3.395%   1272664  (       85.917 -       85.917) [503]
    MediaWiki::performAction                                                         1        81.878        81.878         3.235%   1184620  (       81.878 -       81.878) [483]
    Article::view                                                                    1        59.397        59.397         2.347%    679673  (       59.397 -       59.397) [258]
    SkinTemplate::outputPage-stuff5                                                  1        55.888        55.888         2.208%    456139  (       55.888 -       55.888) [400]
    LocalisationCache::getSubitem-load                                             107        28.478         0.266         1.125%     54868  (        0.240 -        0.468) [428]
    -overhead-total                                                               1570        27.168         0.017         1.073%   1076064  (       27.168 -       27.168) [1570]
    SkinTemplate::outputPage-execute                                                 1        26.111        26.111         1.032%     30494  (       26.111 -       26.111) [398]
    DeferredUpdates::doUpdates                                                       1        25.015        25.015         0.988%       377  (       25.015 -       25.015) [16]
    Skin::buildSidebar                                                               1        21.318        21.318         0.842%     81176  (       21.318 -       21.318) [218]
    ParserCache::get                                                                 1        19.755        19.755         0.781%      1585  (       19.755 -       19.755) [22]
    DynamicSidebar::modifySidebar                                                    1        18.910        18.910         0.747%     69284  (       18.910 -       18.910) [192]
    Linker::titleAttrib                                                             40        18.445         0.461         0.729%     76664  (        0.041 -        1.041) [313]
    CategoryViewer::getHTML                                                          1        17.666        17.666         0.698%    244568  (       17.666 -       17.666) [218]
    query: SELECT lc_value FROM `wiki_lNn_cache` WHERE lc_lang = 'X' LIMIT N       129        15.079         0.117         0.596%    240757  (        0.086 -        0.513) [2]
    LocalisationCache::getItem-load                                                 16        13.923         0.870         0.550%    272404  (        0.259 -        5.256) [100]
    SkinTemplate::outputPage-stuff4                                                  1        11.899        11.899         0.470%    330753  (       11.899 -       11.899) [62]
    Setup.php-globals                                                                1        11.758        11.758         0.465%    567318  (       11.758 -       11.758) [24]
    -overhead-internal                                                            1570        11.512         0.007         0.455%    351680  (        0.006 -        0.046) [0]
    ResourceLoader::makeModuleResponse                                               2        11.067         5.533         0.437%    238877  (        4.679 -        6.388) [36]

I don't know why my setup.php, loadbalancer and db are this slow? Has anyone advice to improve the Performance of these things.

edit: I changed back to configuration without caching and the profiling output looks like:

    Profiling data
Name                                                                         Calls         Total          Each             %       Mem
-total                                                                           1      2264.308      2264.308       100.000%  18818800  (     2264.308 -     2264.308) [0]
LoadBalancer::getConnection                                                    171      1914.577        11.196        84.555%    873694  (        0.010 -      969.956) [183]
LoadBalancer::openConnection                                                   171      1912.571        11.185        84.466%    863369  (        0.002 -      969.939) [12]
DatabaseMysql::open                                                              2      1904.139       952.070        84.094%     13043  (      941.427 -      962.713) [10]
dbconnect-localhost                                                              2      1903.117       951.559        84.049%     12576  (      940.917 -      962.201) [0]
MediaWiki::main                                                                  1      1168.946      1168.946        51.625%   8339081  (     1168.946 -     1168.946) [1546]
MediaWiki::performRequest                                                        1      1052.551      1052.551        46.484%   4786767  (     1052.551 -     1052.551) [728]
SpecialPageFactory::executePath                                                  1      1047.566      1047.566        46.264%   4567696  (     1047.566 -     1047.566) [717]
Setup.php                                                                        1      1045.216      1045.216        46.160%   7760889  (     1045.216 -     1045.216) [55]
Special:Version                                                                  1      1044.117      1044.117        46.112%   4018885  (     1044.117 -     1044.117) [716]
Setup.php-globals                                                                1      1011.005      1011.005        44.650%   4713595  (     1011.005 -     1011.005) [30]
LocalisationCache::getItem-load                                                 15       990.768        66.051        43.756%   1424628  (        0.265 -      979.699) [102]
MessageCache::load                                                               1       943.255       943.255        41.658%     14271  (      943.255 -      943.255) [14]
MessageCache::load-fromcache                                                     1       942.883       942.883        41.641%     13740  (      942.883 -      942.883) [13]
MediaWiki::finalCleanup                                                          1       115.499       115.499         5.101%   3464276  (      115.499 -      115.499) [816]
OutputPage::output                                                               1       113.857       113.857         5.028%   3377273  (      113.857 -      113.857) [809]
Output-skin                                                                      1       102.706       102.706         4.536%   2424168  (      102.706 -      102.706) [806]
SkinTemplate::outputPage                                                         1       102.656       102.656         4.534%   2464206  (      102.656 -      102.656) [805]
SkinTemplate::outputPage-stuff5                                                  1        58.550        58.550         2.586%   1731893  (       58.550 -       58.550) [346]
like image 773
Georg Avatar asked Nov 12 '22 04:11

Georg


1 Answers

From the profiling data you posted it's obvious that the culprit is DB connection open which is brutally slow, the queries themselves seem to be running fast enough. Why it is happening is an interesting question:

  • You didn't mention if your wiki is already public and is receiving traffic or you're its only user ATM?
  • Is MySQL already overloaded for reasons not related to MediaWiki (e.g. because it's a shared host)?
  • Maybe, your MySQL's max_connections is too low and it's idling while clients are desperately waiting in a line to be connected?
like image 75
MaxSem Avatar answered Nov 15 '22 05:11

MaxSem