LoggerFactory::getInstance() does these things:

• checks interface_exists( '\Psr\Log\LoggerInterface' )
  • Should be a simple autoloader hit
• LoggerFactory::getProvider()
  • cached statically after first hit
  • Uses ObjectFactory::getObjectFromSpec() to create factory if not cached
• Spi::getLogger()
  • For WMF prod this is a call to MonologSpi::getLogger()

Since ObjectFactory::getObjectFromSpec() isn't showing up on the report, MonologSpi::getLogger() seems the most likely culprit. MonologSpi uses a memoization pattern to cache and reuse as many objects as it can during a request cycle but it does need to build quite a few object instances in order to deliver a fully functional Monolog\Logger instance. All of these instances are created using ObjectFactory::getObjectFromSpec() which is why I would have expected it to hit the high utilization rather than LoggerFactory::getInstance(), but maybe each call to ObjectFactory::getObjectFromSpec() is fast enough not to get caught on top of the call stack and LoggerFactory::getInstance() just gets blamed because it is wrapping many smaller calls and ending up on top in between each of them? If this was the case however it seems like MonologSpi::getLogger() would really be the one on top of the stack most often.

@bd808 The visual rendering with context can be seen at https://performance.wikimedia.org/xenon/svgs/daily/2015-10-22.api.svgz. Below is a single sample of such stack from e.g. the Parser in an api request:

There is also an inverse flame graph at https://performance.wikimedia.org/xenon/svgs/daily/2015-10-22.api.reversed.svgz.
This can help find the lower-level culprits that have their calls separated over many smaller stacks. Below is the aggregated upside down callstack tip of LoggerFactory::getInstance:

It would seem most calls come from wfDebug (also ObjectCache::newFromParams and wfDebugLog), and LoggerFactory::getInstance itself appears to spend most time (on average) in interface_exists. Monolog doesn't even show up here.

These appear to be more typical traces than the ones in T115729#1749622:

This points where I would expect, namely to the creation of new objects as the time sink.

This trace is starting to make a bit more sense:

This is pointing at the use of ReflectionClass by ObjectFactory as an expensive function. From the doc comments for ObjectFactory::getObjectFromSpec (emphasis added):

Object construction using a specification having both 'class' and 'args' members will call the constructor of the class using ReflectionClass::newInstanceArgs. The use of ReflectionClass carries a performance penalty and should not be used to create large numbers of objects. If this is needed, consider introducing a factory method that can be called via call_user_func_array() instead.

The Monolog configuration that we are using in production & beta cluster builds everything using 'class' + 'args' specifications so we are using ReflectionClass::newInstanceArgs a lot in constructing Logger instances.

I actually wrote that class and docblock so you'd think this would have dawned on me a bit earlier. Apparently not.

PHP 5.6 adds a "splat" operator ([[http://www.php.net/manual/en/migration56.new-features.php#migration56.new-features.splat|...]]) that would allow getObjectFromSpec to use $obj = new $clazz( ...$args ); instead of reflection. The version of HHVM that we are running in production supports splat so it's probably worthwhile to add support for that to ObjectFactory.

Or you can just do something like

switch ( count( $args ) ) {
    case 0:
        return new $clazz();
    case 1:
        return new $clazz( $args[0] );
    case 2:
        return new $clazz( $args[0], $args[1] );
    case 3:
        return new $clazz( $args[0], $args[1], $args[2] );
    default:
        // ...reflection...
}

It's ugly but gets the job done.

Change 248636 had a related patch set uploaded (by BryanDavis):
ObjectFactory: avoid using ReflectionClass

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

Change 248650 had a related patch set uploaded (by BryanDavis):
LoggerFactory: Only check for Psr\Log\LoggerInterface once

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

Change 248636 merged by jenkins-bot:
ObjectFactory: avoid using ReflectionClass

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

Change 248650 merged by jenkins-bot:
LoggerFactory: Only check for Psr\Log\LoggerInterface once

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

Change 249296 had a related patch set uploaded (by Ori.livneh):
ObjectFactory: avoid using ReflectionClass

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

Change 249297 had a related patch set uploaded (by Ori.livneh):
LoggerFactory: Only check for Psr\Log\LoggerInterface once

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

Change 249296 merged by Ori.livneh:
ObjectFactory: avoid using ReflectionClass

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

Change 249297 merged by Ori.livneh:
LoggerFactory: Only check for Psr\Log\LoggerInterface once

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

$ xenon-grep --entrypoint=api --resolution=daily --count=10
Top 10 functions, api.php:
--------------------------
   1 | Elastica\Request::send                | 19.04%
   2 | LuaSandboxFunction::call              | 3.75%
   3 | LuaSandbox::loadString                | 2.89%
   4 | ApiQueryBase::select                  | 2.89%
   5 | ObjectFactory::getObjectFromSpec      | 2.75%
   6 | Revision::fetchFromConds              | 2.63%
   7 | LinkCache::addLinkObj                 | 2.62%
   8 | ObjectFactory::constructClassInstance | 2.54%
   9 | Preprocessor_Hash::preprocessToObj    | 2.47%
  10 | Revision::loadText                    | 2.34%
--------------------------
Log files:
 - /srv/xenon/logs/daily/2015-10-29.api.log
 - /srv/xenon/logs/daily/2015-10-30.api.log

Much better! ObjectFactory::getObjectFromSpec and ObjectFactory::constructClassInstance are still showing up pretty high in the results so there may be additional things to investigate but the reduction from 7.73% to 5.29% (2.75% + 2.54%) is encouraging.

Change 250149 had a related patch set uploaded (by Krinkle):
objectcache: Use singleton cache in newAccelerator()

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

Change 250152 had a related patch set uploaded (by Ori.livneh):
objectcache: Use singleton cache in newAccelerator()

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

Change 250149 merged by jenkins-bot:
objectcache: Use singleton cache in newAccelerator()

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

One OMG! part of this change: interface_exists dropped from 13.14% in https://performance.wikimedia.org/xenon/svgs/daily/2015-10-22.api.reversed.svgz to 0.33% in https://performance.wikimedia.org/xenon/svgs/daily/2015-10-30.api.reversed.svgz

Change 250152 merged by jenkins-bot:
objectcache: Use singleton cache in newAccelerator()

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