[pmwiki-users] Question regarding slow page loading with attr set

Sat Apr 13 09:31:38 PDT 2024

On 13/04/2024 14:50, Hans Bracker wrote:
...
> 17: 00.02 UpdatePage: end Test.Post4
> 18: 0.02 FoxHandlePost: end
> 19: 00.02 FoxFinish start
> 20: 00.03 MarkupToHTML begin
> 21: 00.04 MarkupToHTML end
...
> 17: 01.51 UpdatePage: end Test.Post5
> 18: 1.51 FoxHandlePost: end
> 19: 01.51 FoxFinish start
> 20: 01.88 MarkupToHTML begin
> 21: 04.15 MarkupToHTML end

 From your StopWatch listings it seems the page with password is saved 
slower (UpdatePage: end), but then when the subsequent processing is 
much much slower, and in most cases the slowness happens inside 
MarkupToHTML.

There is a similar phenomenon with the regular edit form for a page with 
an edit password, although much less extreme, when there is a 
conditional markup (:if auth edit:) in a page. In this case on my wiki 
processing of Site.SideBar and Site.PageActions is slightly slower as 
they both have an (:if auth edit:) conditional.

Authentication conditionals are not fully cached, and the conditional 
markup calls RetrieveAuthPage() which actually opens the disk file for 
the target page (in this case the current page), and reads the page text 
and metadata (but not the whole history) then checks the session 
passwords against the "passwdedit" attributes.

RetrieveAuthPage() also opens the disk file for Group.GroupAttributes, 
but only once, and the group permissions are cached.

Finally, the recent PHP function password_verify() that we use, is "safe 
against timing attacks", which means may be idling to match the slowest 
possible calculation time before returning the answer.

On my 5-year old laptop, each edit conditional for the current page 
takes approximately 0.20 seconds more than the processing of the text 
block, which only takes 0.02 without a page password.

If your page text, or your sidebar, page actions, header, footer, have 
multiple conditionals, for example a pagelist with such a conditional in 
a template, or if Fox or another recipe calls CondAuth() or 
RetrieveAuthPage() multiple times, this may be the reason for the 
slowness.

I wonder if we could cache the results of (:if auth...:) per $pagename 
and per $level, rather than doing the full RetrieveAuthPage() every 
time. Once markup is processed, every possible authentication is 
normally available for the session.

I am not ready to cache results for RetrieveAuthPage() as recipes may 
call it much earlier.

Petko

On 13/04/2024 16:19, Hans Bracker wrote:
> PS:
> so the question comes down to this:
> what makes a page to load so much slower, seconds slower, when a page
> password attribute is set to the page with ?action=attr
> 
> I observe this too with the pmwiki and pmwiki-responsive skins, even
> though they are slightly faster than the amber skin I am using mainly,
> because they have less calls to MarkupToHTML

On 13/04/2024 14:50, Hans Bracker wrote:
> Hi, I am trying to find out why a page save takes a lot longer when
> there is a page attribute set, compared to where a global password is
> used.
> For testing I got identical pages. One has an edit password set as
> page attribute (?action=attr), the other is just protected via a
> global edit password in config.php.
> Setting in config.php
> $EnableDiag = 1;
> $EnableStopWatch = 1;
> I get these two stopwatch logs for identical actions, using a fox form
> processing to save to the page:
> (Just noticing: actually even the display of these pages, without any
> saving, takes 5.4secs for the page with attribute, but only 0.05 secs
> for the one without!)
> 
> On the page without page edit attribute (just the global edit
> password): 0.09 secs
> ===============================
> 0: 0.00 FoxHandlePost: begin
>  1: 00.00 FoxProcessTargets: begin $tn
>  2: 0.00 FoxProcessTargets: Test.Post4
>  3: 00.00 UpdatePage: begin Test.Post4
>  4: 00.00 UpdatePage: ReplaceOnSave (Test.Post4)
>  5: 00.00 UpdatePage: SaveAttributes (Test.Post4)
>  6: 00.00 MarkupToHTML begin
>  7: 00.01 MarkupToHTML end
>  8: 00.01 UpdatePage: MergeLastMinorEdit (Test.Post4)
>  9: 00.01 UpdatePage: SaveChangeSummary (Test.Post4)
> 10: 00.01 UpdatePage: PostPage (Test.Post4)
> 11: 00.01 PHPDiff: begin
> 12: 00.01 PHPDiff: end
> 13: 00.01 UpdatePage: PostRecentChanges (Test.Post4)
> 14: 00.02 UpdatePage: FoxPostNotify (Test.Post4)
> 15: 00.02 UpdatePage: PostPageIndex (Test.Post4)
> 16: 00.02 PageIndexQueueUpdate: queued 1 pages (1 total)
> 17: 00.02 UpdatePage: end Test.Post4
> 18: 0.02 FoxHandlePost: end
> 19: 00.02 FoxFinish start
> 20: 00.03 MarkupToHTML begin
> 21: 00.04 MarkupToHTML end
> 22: 00.04 MarkupToHTML begin
> 23: 00.04 MarkupToHTML end
> 24: 00.04 MarkupToHTML begin
> 25: 00.04 MarkupToHTML end
> 26: 00.04 MarkupToHTML begin
> 27: 00.04 MarkupToHTML end
> 28: 00.04 MarkupToHTML begin
> 29: 00.05 MarkupToHTML end
> 30: 00.05 MarkupToHTML begin
> 31: 00.06 MarkupToHTML end
> 32: 00.06 MarkupToHTML begin
> 33: 00.07 MarkupToHTML end
> 34: 00.07 MarkupToHTML begin
> 35: 00.09 MarkupToHTML end
> 36: 00.09 now
> 
> On the page with page edit attribute 5.7 secs:
> =====================================
> 0: 0.00 FoxHandlePost: begin
>  1: 00.00 FoxProcessTargets: begin $tn
>  2: 0.22 FoxProcessTargets: Test.Post5
>  3: 00.22 UpdatePage: begin Test.Post5
>  4: 00.22 UpdatePage: ReplaceOnSave (Test.Post5)
>  5: 00.22 UpdatePage: SaveAttributes (Test.Post5)
>  6: 00.22 MarkupToHTML begin
>  7: 01.50 MarkupToHTML end
>  8: 01.50 UpdatePage: MergeLastMinorEdit (Test.Post5)
>  9: 01.50 UpdatePage: SaveChangeSummary (Test.Post5)
> 10: 01.50 UpdatePage: PostPage (Test.Post5)
> 11: 01.50 PHPDiff: begin
> 12: 01.50 PHPDiff: end
> 13: 01.50 UpdatePage: PostRecentChanges (Test.Post5)
> 14: 01.51 UpdatePage: FoxPostNotify (Test.Post5)
> 15: 01.51 UpdatePage: PostPageIndex (Test.Post5)
> 16: 01.51 PageIndexQueueUpdate: queued 1 pages (1 total)
> 17: 01.51 UpdatePage: end Test.Post5
> 18: 1.51 FoxHandlePost: end
> 19: 01.51 FoxFinish start
> 20: 01.88 MarkupToHTML begin
> 21: 04.15 MarkupToHTML end
> 22: 04.16 MarkupToHTML begin
> 23: 04.16 MarkupToHTML end
> 24: 04.16 MarkupToHTML begin
> 25: 04.58 MarkupToHTML end
> 26: 04.58 MarkupToHTML begin
> 27: 04.59 MarkupToHTML end
> 28: 04.59 MarkupToHTML begin
> 29: 04.80 MarkupToHTML end
> 30: 04.80 MarkupToHTML begin
> 31: 05.27 MarkupToHTML end
> 32: 05.27 MarkupToHTML begin
> 33: 05.49 MarkupToHTML end
> 34: 05.49 MarkupToHTML begin
> 35: 05.70 MarkupToHTML end
> 36: 05.70 now
> 
> Something different after the page is saved seems happening in the
> second case. Not sure , or what to look for, just noticing a real
> slowdown if I have a page attribute (page password) set.
> Thanks for any hints!