Thread

Ok, Carolyn, in addition to the ones you already have, can you place one on lines 1526, 1548, 1550,and 1565?  And I meant to just put the line number in the log message itself, i.e.:

$TMPL->log_item('Line 1526');

But a descriptive message like you have is fine too.

You appear to be losing a crazy amount of time in a wee bit of typography and date parsing, so I’d like to nail it down to which.

Seems its between 1526 and 1548 BUT only on certain articles (since some responses seem ok) so displayed the wiki article name and guess what? articles with the delay seem to be those which are predominantly if not all html tables, largest delays are entries with multiple links ... :coolhmm: (ref: earlier thread 43241… could this be php 5.2 related (PCRE backtrack and recursion limits)?)

(0.593043) In recent_changes function in mod.wiki.php going into loop for results
(0.594046) line 1526 btwn article & data
(17.003927) line 1548 btwn link & data
(17.005559) line 1550 after prep conditionals
(17.010628) line 1565 before gmt rev dt processing
(17.010750) In recent_changes function in mod.wiki.php parse switch var stuff
(17.011191) In recent_changes function in mod.wiki.php parse switch var stuff end
(17.011790) line 1526 btwn article & data
(17.223927) line 1548 btwn link & data
(17.226010) line 1550 after prep conditionals
(17.237364) line 1565 before gmt rev dt processing
(17.237517) In recent_changes function in mod.wiki.php parse switch var stuff
(17.237720) In recent_changes function in mod.wiki.php parse switch var stuff end
(17.238242) line 1526 btwn article & data
(20.011630) line 1548 btwn link & data
(20.013577) line 1550 after prep conditionals
(20.019761) line 1565 before gmt rev dt processing
(20.019848) In recent_changes function in mod.wiki.php parse switch var stuff
(20.020324) In recent_changes function in mod.wiki.php parse switch var stuff end
(20.020859) line 1526 btwn article & data
(51.629828) line 1548 btwn link & data
(51.631651) line 1550 after prep conditionals
(51.637996) line 1565 before gmt rev dt processing
(51.638148) In recent_changes function in mod.wiki.php parse switch var stuff
(51.638353) In recent_changes function in mod.wiki.php parse switch var stuff end
(51.639029) line 1526 btwn article & data
(56.372932) line 1548 btwn link & data
(56.374258) line 1550 after prep conditionals

What next?

-C

Yes, that seems a logical conclusion, though the modifications made in xss_clean() were incorporated into EE 1.6 circumvent that issue greatly, with much improved performance and exponentially fewer PCRE backtracks on blocks of text like you are describing.  Can you go ahead and update your files to the latest build just released today to make sure your files are fresh?

If you do not see an improvement, can you do a backup of your wiki tables and email them to me?

Thank you. Will update build. Will report back (probably tomorrow US CDT).

Updated to the 6/26 build and no disco…same issue… will zip and email wiki dbs shortly to ya, Derek. Thank you ...

Here’s the info from my testing after I added back in a couple of debugging statements:
(0.291239) Calling Class/Method: Wiki/wiki
(0.292402) -> Class Called: Wiki
(0.673910) Line 1531 just created URL about to set up data array
(0.675986) Line 1544 done with array and setting up article
(21.798375) Line 1531 just created URL about to set up data array
(21.799417) Line 1544 done with array and setting up article
(22.081422) Line 1531 just created URL about to set up data array
(22.082504) Line 1544 done with array and setting up article
(25.676253) Line 1531 just created URL about to set up data array
(25.680050) Line 1544 done with array and setting up article
(66.707203) Line 1531 just created URL about to set up data array
(66.708100) Line 1544 done with array and setting up article
(72.020805) Line 1531 just created URL about to set up data array
(72.022074) Line 1544 done with array and setting up article
(72.331956) Line 1531 just created URL about to set up data array
(72.332597) Line 1544 done with array and setting up article
(72.472469) Line 1531 just created URL about to set up data array
(72.473513) Line 1544 done with array and setting up article
(72.518588) Line 1531 just created URL about to set up data array
(72.519894) Line 1544 done with array and setting up article
(72.653250) Line 1531 just created URL about to set up data array
(72.654453) Line 1544 done with array and setting up article
(72.777120) Line 1531 just created URL about to set up data array
(72.778638) Line 1544 done with array and setting up article
(73.031676) Line 1531 just created URL about to set up data array
(73.033195) Line 1544 done with array and setting up article
(73.066497) Line 1531 just created URL about to set up data array
(73.068453) Line 1544 done with array and setting up article
(73.101060) Line 1531 just created URL about to set up data array
(73.103592) Line 1544 done with array and setting up article
(73.138894) Line 1531 just created URL about to set up data array
(73.140131) Line 1544 done with array and setting up article
(73.190831) Line 1531 just created URL about to set up data array
(73.192406) Line 1544 done with array and setting up article
(73.367584) Line 1531 just created URL about to set up data array
(73.369022) Line 1544 done with array and setting up article
(73.668355) Line 1531 just created URL about to set up data array
(73.669516) Line 1544 done with array and setting up article
(73.720978) Line 1531 just created URL about to set up data array
(73.728569) Line 1544 done with array and setting up article
(73.759187) Line 1531 just created URL about to set up data array
(73.760290) Line 1544 done with array and setting up article
(74.263401) -> Method Called: wiki
(74.263782) -> Data Returned

Here is my parsing log with your data—running PHP 5.2 and MySQL 5.1

(0.037215) Calling Class/Method: Wiki/wiki
(0.037379) -> Class Called: Wiki
(0.170781) Line 1531 just created URL about to set up data array
(0.171227) Line 1544 done with array and setting up article
(0.230231) Line 1531 just created URL about to set up data array
(0.230657) Line 1544 done with array and setting up article
(0.246516) Line 1531 just created URL about to set up data array
(0.246915) Line 1544 done with array and setting up article
(0.264982) Line 1531 just created URL about to set up data array
(0.265376) Line 1544 done with array and setting up article
(0.377995) Line 1531 just created URL about to set up data array
(0.378483) Line 1544 done with array and setting up article
(0.464824) Line 1531 just created URL about to set up data array
(0.465311) Line 1544 done with array and setting up article
(0.471461) Line 1531 just created URL about to set up data array
(0.471949) Line 1544 done with array and setting up article
(0.480240) Line 1531 just created URL about to set up data array
(0.480723) Line 1544 done with array and setting up article
(0.483291) Line 1531 just created URL about to set up data array
(0.483730) Line 1544 done with array and setting up article
(0.486787) Line 1531 just created URL about to set up data array
(0.487230) Line 1544 done with array and setting up article
(0.490830) Line 1531 just created URL about to set up data array
(0.491273) Line 1544 done with array and setting up article
(0.495613) Line 1531 just created URL about to set up data array
(0.496066) Line 1544 done with array and setting up article
(0.498935) Line 1531 just created URL about to set up data array
(0.499379) Line 1544 done with array and setting up article
(0.501737) Line 1531 just created URL about to set up data array
(0.502179) Line 1544 done with array and setting up article
(0.504655) Line 1531 just created URL about to set up data array
(0.505095) Line 1544 done with array and setting up article
(0.507978) Line 1531 just created URL about to set up data array
(0.508469) Line 1544 done with array and setting up article
(0.512678) Line 1531 just created URL about to set up data array
(0.513135) Line 1544 done with array and setting up article
(0.519074) Line 1531 just created URL about to set up data array
(0.519547) Line 1544 done with array and setting up article
(0.522341) Line 1531 just created URL about to set up data array
(0.522785) Line 1544 done with array and setting up article
(0.525489) Line 1531 just created URL about to set up data array
(0.525961) Line 1544 done with array and setting up article
(0.548163) -> Method Called: wiki
(0.548196) -> Data Returned

I used your debugging message so it would be easy to compare.  On the same articles, you can see that it is taking longer to parse certain articles, only on your server, it’s taking an inordinate amount of time.  An extra .04 seconds on mine vs. 21 full seconds on yours, for instance.

What I want you to do now is to start reducing processing until the speed is alleviated as follows.  This would be very quick to debug if I could have access to the server, but since that’s not the case, you’re going to need to have some patience so we can narrow this down to the exact function and statement choking things.

On line 1545, start with:

$data['{article}'] = $this->convert_curly_brackets($TYPE->parse_type( $this->wiki_syntax($row['page_content']), 
                      array(
                            'text_format'   => $this->text_format,
                            'html_format'   => $this->html_format,
                            'auto_links'    => $this->auto_links,
                            'allow_img_url' => 'y'
                          )
                    ));

Then:

$data['{article}'] = $this->convert_curly_brackets($TYPE->parse_type( $row['page_content'], 
                      array(
                            'text_format'   => $this->text_format,
                            'html_format'   => $this->html_format,
                            'auto_links'    => $this->auto_links,
                            'allow_img_url' => 'y'
                          )
                    ));

Then:

$data['{article}'] = $this->convert_curly_brackets($row['page_content']);

And report back on the affected time for parsing that each modification had.  Then we’ll drill down further.

Reporting:
Labeled as “part 1”, “part 2”, “part 3”. Between parts 2 & 3 timing is quick (.0003 - .002) so I think we can rule out the 3rd part as the culprit.

Parts 1 & 2 however look equally culpable for the delay when <big?> HTML tables are being processed.

The wiki article with page_content that’s ~43rows X 8col HTML table (with no links) is the biggest offender taking over a minute in just this bit of code alone:

(50.503576) Line 1531 just created URL about to set up data array where topic ##masked topic name of html table without links##
(50.505823) Line 1544 done with array and setting up article
(95.753296) Was Line 1544 split out code for article after part 1
(134.816153) Was Line 1544 split out code for article after part 2
(134.819564) Was Line 1544 split out code for article after part 3

This test is actually pushing response to over 2 minutes.  🐛 Patience? Me - Not a problem. My users? ‘nother story.

Second worst offender is the table with all the links that’s ~40rows X 4cols HTML table.

(0.682330) Line 1531 just created URL about to set up data array where topic ##masked topic name of html table with links##
(0.684962) Line 1544 done with array and setting up article
(21.849498) Was Line 1544 split out code for article after part 1
(43.386058) Was Line 1544 split out code for article after part 2
(43.388118) Was Line 1544 split out code for article after part 3

Awaiting further instructions 😉

Sorry, I don’t guess I was clear enough.  I wanted you to start with the first code, which is the original, and then replace it with the second, and then the third. 😉  This works fine, though.

I think that narrows it down to typography, and do you remember how I said in the other thread about that one chap’s weblog entries tag parsing so slowly that the two issues were unrelated?  Well after a couple hours debugging on his server, I think you have the same problem.  In a plain PHP file, place the following:

<?php

list($usec, $sec) = explode(" ", microtime());
$start = ((float)$usec + (float)$sec);

for($i = 0; $i < 1000; $i++)
{
    uniqid('');
}

list($usec, $sec) = explode(" ", microtime());
$end = ((float)$usec + (float)$sec);

$time = number_format(($end - $start), 6);

echo $time;

?>

What is the output when accessing this in your browser?

Varies from 0.012569 up to 0.023229.

The good news is - you aren’t affected by the same problem.

The bad news is - we have to keep looking.  Open core.regex.php, and at the top of xss_clean(), put:

return $str;

Please make sure the site is offline to everyone but Super Admins, and remove this line immediately after testing.

Doesn’t seem to have much impact so I guess that eliminates xss_clean causing the slowdown?
The wiki article with page_content that’s ~43rows X 8col HTML table (with no links) shows the following:
(48.536388) Line 1544 done with array and setting up article
(92.792067) Was Line 1544 split out code for article after part 1
(137.818303) Was Line 1544 split out code for article after part 2

(Did I mention I’m still fairly new to php relative to others on this forum? Sorry for misunderstanding and glad the results were still meaningful!)

I’ve downloaded yesterday’s build and will apply it shortly in test.
The main wiki users were OK with moving forward with upgrade in production with this known item being worked so that will happen today too. Meanwhile, I have my dev implementation that’s only mine to play in to debug.

-C

Ok, Carolyn.  Let me know after you’ve moved the servers to the latest build (clean files, free of all of our debugging code and modifications), and we’ll go from there.

Actually, can you try setting the formatting type of this wiki to use the No Formatting plugin instead of Textile?

zippy with no formatting - Script Executed in 1.8052 seconds. (without having updated EE to recent build yet)

Can you download the latest version of the Textile plugin and try it?