Here is part of my stack trace after a PHP timeout. I reproduced with different timeout values, identifying the same bottleneck.

10	5.7964	39289688	_taxonomy_multicrud_SubmitHandler->_taxonomy_save_term( )	../taxonomy_multicrud.module:97
11	6.0190	39289320	module_invoke_all( )	../taxonomy_multicrud.module:175
12	6.0191	39292096	call_user_func_array ( )	../module.inc:483
13	6.0191	39292168	pathauto_taxonomy( )	../module.inc:0
14	8.9891	39483528	_taxonomy_pathauto_alias( )	../pathauto.module:377
15	8.9891	39483984	pathauto_get_placeholders( )	../pathauto_taxonomy.inc:106
16	9.0017	39593008	pathauto_clean_token_values( )	../pathauto.inc:453
17	9.1056	39632576	pathauto_cleanstring( )	../pathauto.inc:476
18	9.1056	39641080	pathauto_punctuation_chars( )	../pathauto.inc:99

Having a look at the different functions:

(I do this in a reply post, so I can make corrections)

------------------

So, what's the cure??
We have to be careful with static caching, but
we can cache for the duration of pathauto_get_placeholders(). Especially, the result of t() in pathauto_punctuation_chars().
Ideally this would be done in an object, but as we are in D6 / PHP4 compatible, we could pass a cache array around instead.

(more about this in my reply post)

Comments

donquixote’s picture

Here is an explanation of the stack trace, as promised.
I will use this post as a summary, if this continues.

--------------------------

_taxonomy_multicrud_SubmitHandler->_taxonomy_save_term( )
This is my own version of taxonomy_save_term(), that does not call cache_clear_all().
The custom code is similar to taxonomy_overview_terms_submit(). It loops through a list of terms, and calls taxonomy_save_term() for each of them.

pathauto_taxonomy
called once for each taxonomy_save_term(), via module_invoke_all('taxonomy', ...).

_taxonomy_pathauto_alias()
called once for each pathauto_taxonomy.

pathauto_get_placeholders()
called once for each _taxonomy_pathauto_alias()
Calls token_get_values(), which calls pathauto_cleanstring() and other evil things.
Gets a list of tokens.

pathauto_clean_token_values()
called once for each pathauto_get_placeholders()

pathauto_cleanstring()
called once for each token in the list.
does a lot of variable_get().

pathauto_punctuation_chars()
called once for each pathauto_cleanstring().

t()
called 31 times for each pathauto_punctuation_chars().
calls variable_get(), theme() and locale()

locale()
calls variable_get() and lock_acquire() and db_query().

The result is something like this:
(number of updated / saved terms) * (token_get_values())
(number of updated / saved terms) * 31 * (t / locale + theme + ...)
(number of updated / saved terms) * (number of tokens) * (a lot of variable_get in pathauto_cleanstring)
(number of updated / saved terms) * (number of tokens) * 31 * (t / locale / bunch of db_query + variable_get + lock_acquire + ...)
This hurts.

donquixote’s picture

[ And in this post I will sum up solutions.
For now you can ignore it. ]

greggles’s picture

Title: pathauto_get_placeholders() is a performance nightmare. » make pathauto_get_placeholders() faster

Constructive and drama free posts are more likely to be taken seriously. I look forward to the suggestions for improvement.

donquixote’s picture

hm, yes, sorry for the drama..

dave reid’s picture

Version: 6.x-1.3 » 6.x-1.x-dev

Static caching added to pathauto_punctuation_chars() on all three branches:
http://drupal.org/cvs?commit=385382
http://drupal.org/cvs?commit=385384
http://drupal.org/cvs?commit=385386

greggles’s picture

This seems like an obvious improvement so I don't mind you committing it. I feel like the flow here could have been a little more like the ideal of posting a patch and waiting at least 24 hours before committing.

donquixote’s picture

I was afraid that caching could have side effects, but i think in this case it's really safe. Worst thing (theoretically) could be an updated translation that does not show up in the same request. Really nothing to worry about.

Thanks!
now i can continue with the mass taxonomy editor :)

dave reid’s picture

Sorry about that Greg. Sometimes I need to be subtly reminded to post patches instead of directly committing.

greggles’s picture

@donquixote - does this "fix" the problem in your opinion?

@dave - no worries, it's a really small thing.

donquixote’s picture

I'm playing with Firebug "Net" tab and PHP max_execution_time, on my custom module that tries to save 28 taxonomy terms at once (with title and description).

Firebug Net tab:
without the patch: 55 seconds.
with the patch: 35 seconds.

Setting max_execution_time to a value below 35 can tell me where the script spends its time, showing a stack trace each time it exceeds the limit.

max_execution_time = 1:
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_get_placeholders( ) -> token_get_values( ) -> module_invoke_all( ) -> call_user_func_array ( ) -> pathauto_token_values( ) -> pathauto_cleanstring( )
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_get_placeholders( ) -> pathauto_clean_token_values( ) -> pathauto_cleanstring( )

max_execution_time = 5:
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_create_alias( ) -> _pathauto_alias_exists( )
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_get_placeholders( ) -> pathauto_clean_token_values( ) -> pathauto_cleanstring( )
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_get_placeholders( ) -> pathauto_clean_token_values( ) -> pathauto_cleanstring( ) -> _pathauto_clean_separators( )
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_get_placeholders( ) -> pathauto_clean_token_values( ) -> pathauto_cleanstring( ) -> preg_replace()
pathauto_taxonomy( ) -> _taxonomy_pathauto_alias( ) -> pathauto_create_alias( ) -> _pathauto_alias_exists( ) -> path_redirect_load_multiple( )

max_execution_time = 15:
... -> pathauto_cleanstring() -> mb_eregi_replace()
(I am on PHP 5.2, just for the record)
... -> pathauto_cleanstring() -> _pathauto_clean_separators()

max_execution_time = 25:
... -> pathauto_cleanstring()

max_execution_time = 30:
... -> pathauto_cleanstring()

max_execution_time = 35:
the script finished! yeah!

most of the time it's pathauto_cleanstring(), called in line 476 of pathauto_clean_token_values() (I did not write down all duplicates).

donquixote’s picture

First idea I had was to cache pathauto_get_placeholders(). This is not possible, unfortunately, because the result depends on $object. There can be different placeholder values for each taxonomy term that is saved.

The real problem seems to be that pathauto_get_placeholders() always does the full cleanup for all available tokens.
In fact, it only needs the token keys (like "[tid]" or "[title-raw]"), which are mostly the same for all objects. Then it could use something like preg_replace_callback(), to expand / cleanup only those token values that are actually used in the string.

This is all a bit tricky, and some of it should rather be solved in token.

donquixote’s picture

pathauto.inc, line 300
in pathauto_create_alias().
$alias = str_replace($placeholders['tokens'], $placeholders['values'], $pattern);

This is the only place where $placeholders['values'] is used.
If we replace this with a preg_replace_callback(), we don't have to build the complete $placeholders['values'] any more.

I would really love to do this with some OOP code, but we want to be nice to PHP 4 ..

donquixote’s picture

StatusFileSize
new11.13 KB

The patch is a bit dirty, and it is against 6.x-1.3, not the latest -dev.
I hope you can do anything with it.

Firebug "Net" tab now says 12 seconds.
More results will follow.

EDIT:
Forget this patch. I make a new one.

donquixote’s picture

Update: I found a bug in my own code. I had to set $term['vid'] before sending it to module_invoke_all('taxonomy', $hook, 'term', $term); After fixing this, everything is faster, all of a sudden. It is still the same functions that take most of the time, but it looks like they are called less often.

Increased the number of items to save (around 70 now).
unpatched: 12 seconds
static cache for pathauto_punctuation_chars: 7 seconds
preg_replace_callback: 1.6 seconds.

This means, the patches above do help, at least.
The problem is not as dramatic as I initially thought, but it will become relevant for updating more than 100 terms at once.

Patch will follow.

donquixote’s picture

Version: 7.x-1.x-dev » 6.x-1.x-dev
Status: Needs review » Active
StatusFileSize
new11.58 KB

Here it goes, the patch.
It's against 6.x-1.3, not -dev. sorry for that.
The patch illustrates the idea and it works (in my tests at least), but probably you want to make it a bit nicer.

EDIT:
This patch is meant for D6. No wonder the tests fail.

dave reid’s picture

Version: 6.x-1.x-dev » 7.x-1.x-dev
Status: Active » Needs review
StatusFileSize
new2.92 KB

Here's another patch against HEAD to add some static caching to pathauto_cleanstring().
1. Statically cache if transliteration is enabled and the transliteration module is enabled.
2. Statically cache the punctuation and default variables into an array of keys of search values, and values of replacements. Then any following calls only have to call str_replace().

donquixote’s picture

Version: 6.x-1.x-dev » 7.x-1.x-dev
Status: Active » Needs review

I don't have a working D7 at the moment, so can't test this.
I imagine that the preg_replace_callback idea is still worth to be considered. Is it necessary to port this to D7 first?

dave reid’s picture

Yes, new features will always need to be patched for 7.x-1.x first. Once committed they can be packported to 6.x-2.x.

dave reid’s picture

Title: make pathauto_get_placeholders() faster » Improve performance of pathauto_cleanstring() and pathauto_get_placeholders()
StatusFileSize
new5.64 KB
dave reid’s picture

Issue tags: +Performance
dave reid’s picture

Status: Needs review » Needs work

The last submitted patch, 834198-pathauto-speedup-cleanstring-D7.patch, failed testing.

dave reid’s picture

Status: Needs work » Needs review
StatusFileSize
new5.63 KB

Status: Needs review » Needs work

The last submitted patch, 834198-pathauto-speedup-cleanstring-D7.patch, failed testing.

ISPTraderChris’s picture

I recently installed XHProf and have been systematically profiling my site. I was recently reviewing page load times related to node creation, and was surprised to see that out of about 1000ms worth of processing, about 800ms were spent in pathauto_nodeapi() and auto_nodetitle_nodeapi() -- about 400ms for each. Digging deeper I found that pathauto_cleanstring() and pathauto_get_placeholders() were the functions primarily responsible, in both cases, for the long load times.

I am definitely interested in any efforts to optimize these functions, and would be happy to contribute if I can help in any way.

donquixote’s picture

@ISPTraderChris (#25):
If you want to help, you could test the D6 patch from #15, port it to D7, and compare with the other patches.
Patch #15 contains a trick with preg_replace_callback(), that I do not find in the other patches.
I do not have the time and patience to do any D7 work atm.

greggles’s picture

In my opinion, Dave's patch #23 is a better solution since it isn't as drastic of a change. It's also ready for D7 and just needs some improvement to figure out what if anything it's doing to the simpletests.

In general, it's true that token generation is slow in D5/D6 and much faster in D7.

dave reid’s picture

Assigned: Unassigned » dave reid
fietserwin’s picture

A further optimization could be to not translate the 32 token descriptions at all if not on the pathauto settings page. This would save 32 translate database calls on each node_edit_form, node_insert and node_update call.

dave reid’s picture

Token descriptions are not fetched on token replacement, so I'm not sure where #29 is coming from.

fietserwin’s picture

#30: I'm using the 2011-01-13 7.x-1.0-beta1 version. I could not apply the most recent patch from this thread, but after applying it manually, the patch (from #23) seems not to change this.

The call tree (upwards):
pathauto_punctuation_chars()
pathauto_cleanstring()
pathauto_clean_token_values()
token replace() (pathauto_clean_token_values passed as callback)
pathauto_create_alias()

called by one of these hooks:
pathauto_form_alter() or
pathauto_node_update_alias() or
pathauto_taxonomy_term_update_alias() or
pathauto_user_update_alias() or
pathauto_blog_update_alias()

Call tree starting form pathauto.admin.inc:
pathauto_punctuation_chars()

pathauto_settings_form() or
pathauto_settings_form_validate()

Thus on every content create, update, and (node) update form the descriptions are fetched and translated without need. By moving the call to t() to the actual use of the 'name' entry, the texts do not get translated on the other cases.

fietserwin’s picture

Oops, I now see where the confusion is coming from (#30 in response to #29). I meant to say 32 punctuation descriptions as gets translated in pathauto_punctuation_chars().

I came to this issue by searching on pathauto_punctuation_chars. But looking at my suggestion and the direction this thread went after #5, it might be better to make it a separate issue. Moreover, the patch for my suggestion won''t influence the patch over here. Therefore see #1043424: Prevent translations when not used

mikeytown2’s picture

StatusFileSize
new1.05 KB

subscribe for 6.x. Looking at a cachegrind of cron.

pathauto_cleanstring get's called 34,778 times on a cron run via _feedapi_invoke_refresh. _feedapi_invoke_refresh only gets called 37 times though. The direct caller is pathauto_clean_token_values which gets called 316 times. This function eats up over a minute for us.

Looking at the code pathauto_cleanstring seems like it could use a static for 6.x

Have yet to put this patch through production to get performance numbers

mikeytown2’s picture

With my 6.x patch function got called 38,402 times but it took under 3 seconds to run (total time). Big improvement with over a minute.

dave reid’s picture

Re-testing and benchmarking this after #1182710: Improve performance of pathauto_get_placeholders() landed which reduces the amount of calls to pathauto_cleanstring() a lot.

dave reid’s picture

Patch attached for 6.x-2.x and benchmarked:

ab -n 50 http://mysql.drupal6dev.local/test.php

test.php:

require_once './includes/bootstrap.inc';
drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
$result = db_query("SELECT nid FROM {node}");
$nids = array();
while ($nid = db_result($result)) {
  $nids[] = $nid;
}
// FYI: count($nids) == 200
pathauto_node_update_alias_multiple($nids, 'bulkupdate');
BEFORE PATCH
------------

Full executions of pathauto_cleanstring(): 505
memory_get_peak_usage(TRUE): 16.75 MB

Requests per second:    0.34 [#/sec] (mean)
Time per request:       2962.172 [ms] (mean)
Time per request:       2962.172 [ms] (mean, across all concurrent requests)
Transfer rate:          0.16 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  2709 2961 765.2   2785    7110
Waiting:     2709 2961 765.2   2785    7110
Total:       2709 2961 765.2   2785    7110


AFTER PATCH
-----------

Full executions of pathauto_cleanstring(): 221
memory_get_peak_usage(TRUE): 17 MB

Requests per second:    0.35 [#/sec] (mean)
Time per request:       2861.152 [ms] (mean)
Time per request:       2861.152 [ms] (mean, across all concurrent requests)
Transfer rate:          0.16 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  2682 2860 441.9   2780    5848
Waiting:     2682 2860 441.7   2780    5847
Total:       2682 2860 441.9   2780    5848
dave reid’s picture

Status: Needs work » Needs review
StatusFileSize
new1.24 KB

Patch re-rolled for D7 to use the fast-version of drupal_static().

dave reid’s picture

Status: Needs review » Fixed

Committed to all three branches:
http://drupalcode.org/project/pathauto.git/commit/e126025
http://drupalcode.org/project/pathauto.git/commit/a698011
http://drupalcode.org/project/pathauto.git/commit/bc31549

I'm going to file a separate issue for the cleanstring optimizations that I attempted.

dave reid’s picture

Status: Fixed » Needs review
StatusFileSize
new6.98 KB

Going to re-attempt the optimizations now in the same issue...

dave reid’s picture

Benchmarks for #39 running with MAMP, a D7 install with various patterns for each node type with 1-5 tokens for each.

ab -n 100 http://mysql.drupal7dev.local/test.php

test.php:

define('DRUPAL_ROOT', getcwd());
require_once DRUPAL_ROOT . '/includes/bootstrap.inc';
drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
$nids = db_query("SELECT nid FROM {node}")->fetchCol(); // FYI: count($nids) == 200
pathauto_node_update_alias_multiple($nids, 'bulkupdate');
BEFORE PATCH
------------

Requests per second:    1.16 [#/sec] (mean)
Time per request:       860.577 [ms] (mean)
Time per request:       860.577 [ms] (mean, across all concurrent requests)
Transfer rate:          0.37 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   814  860  42.5    851    1020
Waiting:      813  859  42.5    851    1020
Total:        814  860  42.5    851    1020


AFTER PATCH
-----------

Requests per second:    1.23 [#/sec] (mean)
Time per request:       812.486 [ms] (mean)
Time per request:       812.486 [ms] (mean, across all concurrent requests)
Transfer rate:          0.39 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   782  811  34.8    799     983
Waiting:      781  811  34.8    799     983
Total:        782  811  34.8    799     983
mikeytown2’s picture

I'll take -50ms any day!

dave reid’s picture

Status: Fixed » Closed (fixed)
Issue tags: -Performance

Automatically closed -- issue fixed for 2 weeks with no activity.