?
avatar Fedik
Fedik
8 Oct 2020

As we all know the logging of deprecated function works always, even when the debug is disabled, that cause a performance issue.
Especially on 4.0 version where is a tons of deprecated methods.

Steps to reproduce the issue

Log in to backend.
Disable debug.

Then edit administrator/index.php,
change:

require_once dirname(__FILE__) . '/includes/app.php';

to:

$starttime = microtime(1);

require_once dirname(__FILE__) . '/includes/app.php';

$endtime = microtime(1);

var_dump($endtime - $starttime);

Visit the Home Dahsboard, and Artciles, and other pages, and note the time that displayed at end of every page.

Then edit libraries/src/Log/Log.php, at beginning on function add() add early return; (mimic disabled logs)

public static function add($entry, $priority = self::INFO, $category = '', $date = null, array $context = array())
{
// Automatically instantiate the singleton object if not already done.
if (empty(static::$instance))

Something like:

public static function add($entry, $priority = self::INFO, $category = '', $date = null, array $context = array())
{
  return;
  // Automatically instantiate the singleton object if not already done.
...
...

Then visit same pages again, and note the time.

Expected result

Time should be around the same

Actual result

Time dropped much (rendering become faster), in my test around 30-50% depend from page. On real hosting it can be much worse.

Additional comments

I would suggest to wrap all such logs in to if (DEBUG), or if ($app->get('log_deprecated')) (when #30317 will be merged)
Or maybe some helper method that will be as proxy-wrapper for deprecated log.

avatar Fedik Fedik - open - 8 Oct 2020
avatar joomla-cms-bot joomla-cms-bot - change - 8 Oct 2020
Labels Added: ?
avatar joomla-cms-bot joomla-cms-bot - labeled - 8 Oct 2020
avatar Fedik Fedik - change - 8 Oct 2020
The description was changed
avatar Fedik Fedik - edited - 8 Oct 2020
avatar brianteeman
brianteeman - comment - 8 Oct 2020

/me confused as I only get the deprecated api logging when I specifically enable it

avatar Fedik
Fedik - comment - 8 Oct 2020

confused as I only get the deprecated api logging when I specifically enable it

The issue is when you disable the logging it does not disable logging itself, you just not see it ;)

Example look:

public static function register($key, callable $function)
{
try
{
Log::add(
'Support for registering functions is deprecated and will be removed in Joomla 5.0, use the service registry instead',
Log::WARNING,
'deprecated'
);
}
catch (\RuntimeException $exception)
{
// Informational message only, continue on
}

It always call Log:add(), no mater if you have enabled logging or not.

avatar brianteeman
brianteeman - comment - 8 Oct 2020

ah - I see what you mean now

avatar Fedik Fedik - change - 8 Oct 2020
The description was changed
avatar Fedik Fedik - edited - 8 Oct 2020
avatar HLeithner
HLeithner - comment - 9 Oct 2020

That's the reason why we have to find ways to log deprecation calls only once like the $app->isAdmin() function... but that's not so easy because if you call it only once then you see only one stacktrace and have to fix this then with the next call you see the next stackstrace and have to fix this and so on....

And I think that's the reason why isAdmin() and isSite() doesn't have Log entries and only the deprecation comment. To get all depredations you can use https://api.joomla.org/cms-3/deprecated.html

avatar jiweigert
jiweigert - comment - 9 Oct 2020

On my own preference,
I would like to have a performant site were the Log function is not called everytime regardless of my Logging settings.

A possible solution could be a ontime check on depricated functions when enabling that plugin and showing a warning modal that this plugin uses <depricated function> and the developer should not use this function.

Yes, that would mean, the average user would get that message too, when he enable that plugin / extension, but only once.


This comment was created with the J!Tracker Application at issues.joomla.org/tracker/joomla-cms/30997.
avatar Fedik
Fedik - comment - 9 Oct 2020

@HLeithner @wilsonge what do you think about some "proxy" helper?
kind of like this:

class LogHelper
{
  public static function deprecatedMethod($method, $endVersion, $message = '')
  {
      if (!Factory::getAplication()->get('log_deprecated'))
      {
          return;
      }

      try
      {
          Log::add(
              sprintf('% is deprecated, and will be removed in %s.%s', $method, $endVersion, ($message ? ' ' . $message : '')),
              Log::WARNING,
              'deprecated'
          );
      }
      catch (\RuntimeException $exception)
      {
          // Silents
      }
  }
}

Then just call:

LogHelper::deprecatedMethod(__METHOD__, '5.0');
avatar HLeithner
HLeithner - comment - 9 Oct 2020

a static cache for getApplication()->get('log_deprecated') could make sense

avatar Fedik
Fedik - comment - 9 Oct 2020

I also thought, or some constant

avatar HLeithner
HLeithner - comment - 9 Oct 2020

Actually we shouldn't introduce any global or static constants but since this is a Application wide setting I think something like

static $logDeprecated = null;

if (!is_null($logDeprecated)) {
  $logDeprecated = Factory::getAplication()->get('log_deprecated');
}

should fit our needs.

but maybe a static public function could help extension developer to be more flexible...

avatar HLeithner
HLeithner - comment - 11 Oct 2020

@Fedik maybe a bad idea but including this in Log::add and check for category would be the easiest way for us if all our deprecation entries using the correct $category 'deprecated'

avatar Fedik
Fedik - comment - 11 Oct 2020

yea, a bit hacky :)
I think use of helper will add more consistency with "deprecation".

I will prepare PR, when will get some time.

avatar HLeithner
HLeithner - comment - 11 Oct 2020

the only thin I will prevent is to rewrite all deprecation entries... I would not introduce a new class I would use the Log class and add a LogDeprecated function if not directly in the log function

avatar alikon
alikon - comment - 12 Oct 2020

why just not do something like this

// We only want to handle user deprecation messages, these will be triggered in code
if ($errorNumber === E_USER_DEPRECATED)
{			
    // If debug mode is enabled, we want to let PHP continue to handle the error; otherwise, we can bail early
    if (\defined('JDEBUG') && JDEBUG)
    {
	Log::add(
	    $errorMessage,
	     Log::WARNING,
	     'deprecated'
	);

	return true;
     }

}

instead of https://github.com/joomla/joomla-cms/blob/4.0-dev/libraries/src/Exception/ExceptionHandler.php#L39-L53

avatar brianteeman
brianteeman - comment - 12 Oct 2020

That's the reason why we have to find ways to log deprecation calls only once

This seems wrong to me. The purpose of a log is to log things. Not to see if it has been logged before. If I load a page that should log something then I would expect to see it in the log. How else would I know there is an issue.

I visit page 1 and it logs "issue with function a"
I visit page 2 and it doesn't log "issue with function a" because there is already a log entry for "issue with function a"

How does that help me? I would think there is nothing wrong with page 2.

avatar Fedik
Fedik - comment - 12 Oct 2020

@brianteeman you misunderstood, @HLeithner talked about call "per request",
In your example it will log on page 1 and page 2, but only once per page.

However it still has limitation, he wrote it in the same comment ;)

avatar Fedik
Fedik - comment - 12 Oct 2020

@alikon that logging for PHP deprecations,

Of course we can trigger them also with:

trigger_error('Method ' . __METHOD__ . ' is deprecated', E_USER_DEPRECATED);

but I am not sure here, whether this approach have any performance issue.

avatar Fedik Fedik - change - 18 Oct 2020
Status New Closed
Closed_Date 0000-00-00 00:00:00 2020-10-18 10:00:08
Closed_By Fedik
avatar Fedik Fedik - close - 18 Oct 2020
avatar Fedik
Fedik - comment - 18 Oct 2020

Please review and test #31143

Add a Comment

Login with GitHub to post a comment