[v2.108 - BUG?] Slow Loop Parse for expression Topic is solved

Report problems with documented functionality
HotKeyIt
Posts: 2364
Joined: 29 Sep 2013, 18:35
Contact:

[v2.108 - BUG?] Slow Loop Parse for expression

Post by HotKeyIt » 20 Jan 2020, 19:57

Following Code is totally slow while using just the variable is 10-15 times faster

Code: Select all

t:=A_TickCount
Loop Parse, (1,String) ; around 10 times slower than: Loop Parse, String
  continue
MsgBox A_TickCount-t

User avatar
kczx3
Posts: 1640
Joined: 06 Oct 2015, 21:39

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by kczx3 » 20 Jan 2020, 21:27

Does it seem to matter what the variable string contains? So the evaluation of that expression is causing the degraded performance then?

swagfag
Posts: 6222
Joined: 11 Jan 2017, 17:59

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by swagfag » 21 Jan 2020, 00:13

what is this bug report for again?
ur examples bench roughly the same, cold start, separate files, v2.108:

Code: Select all

DllCall('QueryPerformanceCounter', 'Int64*', start := 0)
Loop Parse, String
	continue
DllCall('QueryPerformanceCounter', 'Int64*', end := 0)
MsgBox end - start ; 55-70

Code: Select all

DllCall('QueryPerformanceCounter', 'Int64*', start := 0)
Loop Parse, (1,String) ; around 10 times slower than: Loop Parse, String
	continue
DllCall('QueryPerformanceCounter', 'Int64*', end := 0)
MsgBox end - start ; 60-75
the second version is slower for sure having to unpack and evaluate two expressions, but certainly nowhere near as much as ure claiming
where is the 10x slowdown?

User avatar
nnnik
Posts: 4500
Joined: 30 Sep 2013, 01:01
Location: Germany

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by nnnik » 21 Jan 2020, 07:59

That would probably happen if the expression is reevaluated every iteration - so for it to happen you need iterations - possibly many of them.
Recommends AHK Studio

swagfag
Posts: 6222
Joined: 11 Jan 2017, 17:59

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by swagfag » 21 Jan 2020, 08:13

evaluated on every iteration of what? the expression is evaluated only once before the loop starts
or if ure talking about looping the loopparse, even so, this wouldnt cause a 10x slowdown

User avatar
nnnik
Posts: 4500
Joined: 30 Sep 2013, 01:01
Location: Germany

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by nnnik » 21 Jan 2020, 08:20

It would because the string gets copied every time - possibly even multiple times.
It only getting evaluated once is an assumption - if it really is 10 times slower this would be a possible cause.
Recommends AHK Studio

swagfag
Posts: 6222
Joined: 11 Jan 2017, 17:59

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by swagfag » 21 Jan 2020, 09:21

what do u mean an "assumption"? its an assertion. and a damn easy one at that to test urself. Loop Parse's String expression is evaluated once before the loop starts.
the string would have to be copied in both examples, so the point is moot. besides, introducing long strings into the benchmark would only serve to muddy the results as their copying would by far eclipse whatever time differences exist between String and (1, String)

HotKeyIt
Posts: 2364
Joined: 29 Sep 2013, 18:35
Contact:

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by HotKeyIt » 21 Jan 2020, 15:55

For an around 12 MB file:

Code: Select all

Loop Parse, String ; takes about 300 MSec for me
Loop Parse, (1,String) ; for same file takes about 6200 MSec for me
This is 20 times slower.

expression does not seem to be evaluated, so t and i contain the same number:

Code: Select all

t:=A_TickCount
Loop Parse, (i:=A_TickCount,String)
  continue
MsgBox (A_TickCount-t) "`nstart:`t" t "`nloop:`t" i "`nnow:`t" A_TickCount

User avatar
kczx3
Posts: 1640
Joined: 06 Oct 2015, 21:39

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by kczx3 » 21 Jan 2020, 16:07

HotKeyIt wrote:
21 Jan 2020, 15:55
For an around 12 MB file:

Code: Select all

Loop Parse, String ; takes about 300 MSec for me
Loop Parse, String ; for same file takes about 6200 MSec for me
This is 20 times slower.
Was the second Loop Parse supposed to have the (1, String) part in this example?


User avatar
kczx3
Posts: 1640
Joined: 06 Oct 2015, 21:39

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by kczx3 » 21 Jan 2020, 16:23

I think this is just going to require a dive into the source to figure out what is going on.

Are you saying that you'd assume i to be fractionally larger than t if i were actually being evaluated? Or do you just mean that i is only evaluated once at the start of the parsing loop?

I did each with a 96MB file. Using (1, String) took 152984 milliseconds and using just string took 4860 milliseconds.

I think you might look at changing your example though. For me, this makes more sense and exhibits the same slowdown. This seems much more practical to do.

Code: Select all

t:=A_TickCount
Loop Parse, String . "TEST"
  continue
MsgBox (A_TickCount-t) "`nstart:`t" t "`nloop:`t" i "`nnow:`t" A_TickCount
As you'd expect, moving the string concatenation to be prior to the Loop Parse resolves the slowdown.

swagfag
Posts: 6222
Joined: 11 Jan 2017, 17:59

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by swagfag » 23 Jan 2020, 18:24

theres some(up to) 10 second timer(what the fuck) that keeps firing if u give it too large a string
Spoiler

Code: Select all

; LARGE_DEREF_BUF_SIZE = 4 194 304
Loop Parse, ('' . 4_194_303_or_fewer_char_string) ; this is fine
	continue

Loop Parse, ('a' . 4_194_303_char_string) ; lag
	continue

HotKeyIt
Posts: 2364
Joined: 29 Sep 2013, 18:35
Contact:

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by HotKeyIt » 24 Jan 2020, 21:32

The problem here is that sDerefBuf of previous line (Loop) is taken over by next line(s) so SET_DEREF_TIMER is launched every iteration:

Code: Select all

ResultType Line::ExpandArgs(ResultToken *aResultTokens)
...
	// Always init our_buf_marker even if zero iterations, because we want to enforce
	// the fact that its prior contents become invalid once we're called.
	// It's also necessary due to the fact that all the old memory is discarded by
	// the above if more space was needed to accommodate this line.
	LPTSTR our_buf_marker = sDerefBuf;  // Prior contents of buffer will be overwritten in any case.
I think to solve that, PerformLoopParse[CSV] will need to free the sDerefBuf right after copy of the content has been done:

Code: Select all

ResultType Line::PerformLoopParse(ResultToken *aResultToken, bool &aContinueMainLoop, Line *&aJumpToLine, Line *aUntil)
...
	_tcscpy(buf, ARG1); // Make the copy.

	// Make a copy of ARG2 and ARG3 in case either one's contents are in the deref buffer, which would
	// probably be overwritten by the commands in the script loop's body:
	TCHAR delimiters[512], omit_list[512];
	tcslcpy(delimiters, ARG2, _countof(delimiters));
	tcslcpy(omit_list, ARG3, _countof(omit_list));
	
	// Free deref buffer otherwise each call to ExpandArgs will cause a slowdown by calling SET_DEREF_TIMER if sDerefBufSize > LARGE_DEREF_BUF_SIZE.
	if (Line::sDerefBuf && Line::sDerefBufSize > LARGE_DEREF_BUF_SIZE)
	{
		free(Line::sDerefBuf);
		--Line::sLargeDerefBufs;
		SET_S_DEREF_BUF(NULL, 0);
	}
I also noticed another slowdown but I have no idea where it is coming from:

Code: Select all

Loop 520188 ; create long string
   s.="a"
; this Loop runs for around 30 Seconds when s is 510188 characters
; same Loop runs only for 3 seconds when s is    520187 characters
t:=A_TickCount
Loop 100000
  if ("" s)
   continue
MsgBox A_TickCount-t

swagfag
Posts: 6222
Joined: 11 Jan 2017, 17:59

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by swagfag » 25 Jan 2020, 20:03

thats because of something else

lexikos
Posts: 9553
Joined: 30 Sep 2013, 04:07
Contact:

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by lexikos » 21 Feb 2020, 20:19

It is to be expected that Loop Parse, String is faster than Loop Parse, (1, String). Although technically an expression, the former is not evaluated as such due to optimizations.

HotKeyIt wrote:
24 Jan 2020, 21:32
The problem here is that sDerefBuf of previous line (Loop) is taken over by next line(s) so SET_DEREF_TIMER is launched every iteration:
If that's a problem, it is only because SET_DEREF_TIMER is more costly than expected, in which case that should be addressed separately. For instance, by using SetTimer() sparingly. If the timer was already set, record the "last use" time. When the timer elapses, evaluate whether enough time has passed; if not, calculate and reset the timer so that it will fire 10 seconds after the last use. SetTimer() would be called at most twice in a 10 second period, instead of potentially thousands of times.

The main timer could be utilized, but that would require changing the conditions under which the main timer is active, which risks adding bugs that could break script timers or joystick hotkeys.
I think to solve that, PerformLoopParse[CSV] will need to free the sDerefBuf right after copy of the content has been done:
The deref buf exists to be reused, to reduce the frequent reallocation of temporary memory blocks. By freeing it immediately, you are defeating the purpose. If a large deref buf is needed within the loop, a new one will be allocated, and the cost of SET_DEREF_TIMER will still be incurred repeatedly.

If SET_DEREF_TIMER cannot be optimized or the cost is still too high, we should reevaluate 1) whether large deref bufs should even be reused, and if so, 2) whether they should be freed by some other idle-detection mechanism or not at all. This may apply to everything that uses large deref bufs, not necessarily just Loop Parse; I'm not sure that expressions are capable of creating a large deref buf, but certainly other commands in v1 can.

lexikos
Posts: 9553
Joined: 30 Sep 2013, 04:07
Contact:

Re: [v2.108 - BUG?] Slow Loop Parse for expression

Post by lexikos » 07 Dec 2022, 16:21

I finally implemented a fix for this in v1.1.36.02.

The cost of calling SetTimer is relatively low; maybe 12µs. It is noticeable in the example case (a character-by-character parsing loop of "an around 12MB file") because each iteration is more like 0.3µs, and there are some 2.5 million iterations per second (without the SetTimer overhead).

lexikos
Posts: 9553
Joined: 30 Sep 2013, 04:07
Contact:

Re: [v2.108 - BUG?] Slow Loop Parse for expression  Topic is solved

Post by lexikos » 10 Dec 2022, 07:21

Also fixed by v2.0-rc.3.

Post Reply

Return to “Bug Reports”