Timeit f-string performance for self assignments

[AndreCimander]

Bug report

Bug description:

After a long, semi-happy benchmark weekend (darn those non-deterministic instruction counts, even without GC and PYTHONHASHSEED set and exclusive core pinning...) I just stumbled onto an issue with f-string performance under timeit runtime when assigning to one of the joined variables.

Tested with Python 3.11.9 and 3.12.4, Linux (Manjaro OS). Also tested online on various python run time sites to rule out my OS as the culprit.

import timeit

print("String concatenations")
print(timeit.timeit("string3 = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string3 = f'{string}{string2}'")
print(timeit.timeit("string2 = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string2 = f'{string}{string2}'")
print(timeit.timeit("string = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string = f'{string}{string2}'")

String concatenations
0.005295750990626402 string3 = f'{string}{string2}'
6.830826308010728 string2 = f'{string}{string2}'
4.56450519200007 string = f'{string}{string2}'

The slowdown is exponential.

import timeit

print("String concatenations")
print(timeit.timeit("string3 = f'{string}{string2}'", "string='string'; string2='string2'", number=200_000), "string3 = f'{string}{string2}'")
print(timeit.timeit("string2 = f'{string}{string2}'", "string='string'; string2='string2'", number=200_000), "string2 = f'{string}{string2}'")
print(timeit.timeit("string = f'{string}{string2}'", "string='string'; string2='string2'", number=200_000), "string = f'{string}{string2}'")

String concatenations
0.01072984401253052 string3 = f'{string}{string2}'
29.431256133000716 string2 = f'{string}{string2}'
16.437050897002337 string = f'{string}{string2}'

I couldn't replicate this slowdown using python -m timeit or with simple f-string assignment scripts. My guess is an issue with timeit, but maybe this a weird edge case for f-strings?

CPython versions tested on:

3.11, 3.12

Operating systems tested on:

Linux

[Eclips4]

cc @pablogsal

[blhsing]

This is not a bug.

With string3 = f'{string}{string2}' it is a simple concatenation of two strings and an assignment to a new name.

With string2 = f'{string}{string2}', however, you're effectively "growing" string2 by prepending the value of string to it. Since each prepend requires copying the entirety of string2, the time complexity becomes quadratic when the prepend is done repeatedly.

[skirpichev]

Hmm, @AndreCimander, your print() statements produce slightly misleading output, as in last two cases you make assignment to the variable, that is used in concatenation. What's going on in fact:

import timeit

print("String concatenations")
print(timeit.timeit("string3 = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string3 = f'{string}{string2}'")
print(timeit.timeit("string2 = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string2 = f'{string}{string2}'")
print(timeit.timeit("string = f'{string}{string2}'", "string='string'; string2='string2'", number=100_000), "string = f'{string}{string2}'")

Ditto for the second case. Could you please explain what you meant by "slowdown is exponential"?

@blhsing, I might guess OP worry that timings grow non-linearly:) But I don't see this from his two points:

>>> 0.01072984401253052/2  # ~ 0.005295750990626402 from 1st test
0.00536492200626526
>>> 29.431256133000716/2  # ~ 2.15 1st test
14.715628066500358
>>> 16.437050897002337/2  # ~ 1.8 1st test
8.218525448501168

So, there is something expected: timings (last two) grow proportionally to the number of repeated statements (string grow linearly).

Same I can replicate with timeit's CLI:

$ python3.12 -m timeit -n 100000 -u nsec -s 's1="string1";s2="string2"' 's3=f"{s1}{s2}"'
100000 loops, best of 5: 209 nsec per loop
$ python3.12 -m timeit -n 100000 -u nsec -s 's1="string1";s2="string2"' 's1=f"{s1}{s2}"'
100000 loops, best of 5: 1.02e+05 nsec per loop
$ python3.12 -m timeit -n 100000 -u nsec -s 's1="string1";s2="string2"' 's2=f"{s1}{s2}"'
100000 loops, best of 5: 1.05e+05 nsec per loop

$ python3.12 -m timeit -n 200000 -u nsec -s 's1="string1";s2="string2"' 's3=f"{s1}{s2}"'
200000 loops, best of 5: 210 nsec per loop
$ python3.12 -m timeit -n 200000 -u nsec -s 's1="string1";s2="string2"' 's1=f"{s1}{s2}"'
200000 loops, best of 5: 2.32e+05 nsec per loop
$ python3.12 -m timeit -n 200000 -u nsec -s 's1="string1";s2="string2"' 's2=f"{s1}{s2}"'
200000 loops, best of 5: 2.32e+05 nsec per loop

Actually, the last OP printed statement ("string = f'{string}{string}'") - that one should demonstrate something like exponential slowdown. (It's expected too.) And indeed:

$ python3.12 -m timeit -n 10 -u nsec -s 's="string"' 's=f"{s}{s}"'
10 loops, best of 5: 553 nsec per loop
$ python3.12 -m timeit -n 20 -u nsec -s 's="string"' 's=f"{s}{s}"'
20 loops, best of 5: 6.26e+05 nsec per loop
$ python3.12 -m timeit -n 25 -u nsec -s 's="string"' 's=f"{s}{s}"'
25 loops, best of 5: 1.7e+07 nsec per loop

@Eclips4, I think we can close this.

[blhsing]

@blhsing, I might guess OP worry that timings grow non-linearly:) But I don't see this from his two points:

>>> 0.01072984401253052/2  # ~ 0.005295750990626402 from 1st test
0.00536492200626526
>>> 29.431256133000716/2  # ~ 2.15 1st test
14.715628066500358
>>> 16.437050897002337/2  # ~ 1.8 1st test
8.218525448501168

So, there is something expected: timings (last two) grow proportionally to the number of repeated statements (string grow linearly).

@skirpichev Sorry but I don't get what you're saying here. By doubling the number of times the tests are repeated the OP's benchmarks clearly demonstrate that the resulting run time for the string3 case roughly doubles from 0.005295750990626402 to 0.01072984401253052 (2.02612321303 times) while the run times for the cases of string2 and string roughly quadruple from 6.830826308010728 and 4.56450519200007 to 29.431256133000716 (4.3085938371 times) and 16.437050897002337 (3.60105864833 times), respectively. And this is directly because the number of characters copied in the latter cases is k x (1 + 2 + 3 + ... + n) = k x n (n + 1) / 2, or O(n ^ 2) in time complexity, where n is the number of times the test is repeated and k is the number of characters in string being copied.

[skirpichev]

And this is directly because the number of characters copied

Ah, indeed. Timings should be proportional to this, not to the size of resulting string.

[AndreCimander]

@skirpichev I fixed the output of my example, the print output might have lead to some confusion on a quick glance, sorry about that.

I would have expected roughly the same proportional timing increases regardless of appending/prepending and that each case in the appending/prepending cases behaves the same timing-wise.

An extendend example:

bench-fstring.py

import timeit


print()
print("## 100k iterations")

print()
print("# New string control")
print("", timeit.timeit("string3 = f'{string}{string2}'", "string='string_'; string2='string2_'", number=100_000), "string3 = f'{string}{string2}'")

print()
print("# Prepending")
print("", timeit.timeit("string2 = f'{string}{string2}'", "string='string_'; string2='string2_'", number=100_000), "string2 = f'{string}{string2}'")
print("", timeit.timeit("string = f'{string2}{string}'", "string='string_'; string2='string2_'", number=100_000), "string = f'{string2}{string}'")

print()
print("# Appending")
print("", timeit.timeit("string2 = f'{string2}{string}'", "string='string_'; string2='string2_'", number=100_000), "string2 = f'{string2}{string}'")
print("", timeit.timeit("string = f'{string}{string2}'", "string='string_'; string2='string2_'", number=100_000), "string = f'{string}{string2}'")

print()
print("## 200k iterations")

print()
print("# New string control")
print("", timeit.timeit("string3 = f'{string}{string2}'", "string='string_'; string2='string2_'", number=200_000), "string3 = f'{string}{string2}'")

print()
print("# Prepending")
print("", timeit.timeit("string2 = f'{string}{string2}'", "string='string_'; string2='string2_'", number=200_000), "string2 = f'{string}{string2}'")
print("", timeit.timeit("string = f'{string2}{string}'", "string='string_'; string2='string2_'", number=200_000), "string = f'{string2}{string}'")

print()
print("# Appending")
print("", timeit.timeit("string2 = f'{string2}{string}'", "string='string_'; string2='string2_'", number=200_000), "string2 = f'{string2}{string}'")
print("", timeit.timeit("string = f'{string}{string2}'", "string='string_'; string2='string2_'", number=200_000), "string = f'{string}{string2}'")

taskset 0x00000001 bench-fstring.py (excluded core from scheduling and fixed cpu freq):

## 100k iterations

# New string control
 0.007097032997990027 string3 = f'{string}{string2}'

# Prepending
 10.59314832900418 string2 = f'{string}{string2}'
 4.913852167999721 string = f'{string2}{string}'

# Appending
 1.0490332649933407 string2 = f'{string2}{string}'
 2.235699803000898 string = f'{string}{string2}'

## 200k iterations

# New string control
 0.006619192994548939 string3 = f'{string}{string2}'

# Prepending
 33.32355086499592 string2 = f'{string}{string2}'
 18.619490689990926 string = f'{string2}{string}'

# Appending
 4.225575760996435 string2 = f'{string2}{string}'
 6.458956803006004 string = f'{string}{string2}'

[JelleZijlstra]

The self-assignments are slower because timeit updates the variables on each run, so you end up creating longer and longer strings. Creating a long string is slower than creating a short one. You can see this if you modify the benchmark to print each string:

>>> print("", timeit.timeit("string2 = f'{string}{string2}'; print(string2)", "string='string_'; string2='string2_'", number=5), "string2 = f'{string}{string2}'")
string_string2_
string_string_string2_
string_string_string_string2_
string_string_string_string_string2_
string_string_string_string_string_string2_
 4.0125101804733276e-05 string2 = f'{string}{string2}'

Similarly, it's slower if you keep appending string2 to the string, generating a longer string.

I assume the difference between the "prepending" and "appending" benchmarks is because of the way string concatenation is implemented. Executing s1 + s2 to create a new string requires first copying the contents of s1 into the new string, then the contents of s2. It is likely possible to copy s1 faster (because you know that it can be copied to a well-aligned location), so s1 + s2 will be faster if s1 is longer than s2.

I think that explains all the discrepancies seen here, and none of them seem to be bugs.

[AndreCimander]

Yeah, I expected non-linear growth, but this surprised me quite a bit.

Running the same timeit statements multiple times (with force gc.collect between timeit calls) brings the timings into regions that I kinda expected. I also switched prepend/append order and got similar results. It's probably just a memory allocation and cpu cache hit/miss difference?? (Sorry if that's the case 🙇)

But yet still, string2 = f'{string2}{string}' and string = f'{string}{string2}' have differing average timings but are doing the same... shouldn't they have similar timings? 😕

Append first

## 100k iterations

# Appending
 9.795431380989612 string2 = f'{string2}{string}'
 2.624463512998773 string2 = f'{string2}{string}'
 1.6597226510057226 string2 = f'{string2}{string}'
 4.46583334398747 string = f'{string}{string2}'
 2.1261932110064663 string = f'{string}{string2}'
 2.125863631008542 string = f'{string}{string2}'

# Prepending
 1.0152506919985171 string2 = f'{string}{string2}'
 1.0375713410030585 string2 = f'{string}{string2}'
 1.0165787220030325 string2 = f'{string}{string2}'
 2.1402632069948595 string = f'{string2}{string}'
 2.1375688340049237 string = f'{string2}{string}'
 2.137761516001774 string = f'{string2}{string}'

## 200k iterations

# Appending
 31.225929706008174 string2 = f'{string2}{string}'
 5.910085712006548 string2 = f'{string2}{string}'
 6.728694257995812 string2 = f'{string2}{string}'
 18.387449019995984 string = f'{string}{string2}'
 6.221278651995817 string = f'{string}{string2}'
 6.718499934999272 string = f'{string}{string2}'

# Prepending
 4.209730485003092 string2 = f'{string2}{string}'
 4.20804736399441 string2 = f'{string2}{string}'
 4.239082565996796 string2 = f'{string2}{string}'
 6.2295322160061914 string = f'{string}{string2}'
 6.634425401003682 string = f'{string}{string2}'
 6.633589581004344 string = f'{string}{string2}'

Prepend first

## 100k iterations

# Prepending
 9.838094389007892 string2 = f'{string}{string2}'
 2.7064511250064243 string2 = f'{string}{string2}'
 1.7184962530009216 string2 = f'{string}{string2}'
 4.618031942998641 string = f'{string2}{string}'
 2.205591061996529 string = f'{string2}{string}'
 2.2214561069995398 string = f'{string2}{string}'

# Appending
 1.0700150640041102 string2 = f'{string2}{string}'
 1.0742765039904043 string2 = f'{string2}{string}'
 1.0744379849929828 string2 = f'{string2}{string}'
 2.1840694440033985 string = f'{string}{string2}'
 2.19924011999683 string = f'{string}{string2}'
 2.195269157004077 string = f'{string}{string2}'

## 200k iterations

# Prepending
 31.961018079993664 string2 = f'{string2}{string}'
 6.123563083994668 string2 = f'{string2}{string}'
 6.939973419997841 string2 = f'{string2}{string}'
 18.8130047829909 string = f'{string}{string2}'
 6.240597470008652 string = f'{string}{string2}'
 6.750047335997806 string = f'{string}{string2}'

# Appending
 4.2477926410065265 string2 = f'{string2}{string}'
 4.24408394699276 string2 = f'{string2}{string}'
 4.237094145995798 string2 = f'{string2}{string}'
 6.265510519006057 string = f'{string}{string2}'
 6.716748432998429 string = f'{string}{string2}'
 6.631313699996099 string = f'{string}{string2}'

[JelleZijlstra]

But yet still, string2 = f'{string2}{string}' and string = f'{string}{string2}' have differing average timings but are doing the same... shouldn't they have similar timings?

As I mentioned, these result in strings of different lengths.

[AndreCimander]

Ahhhh, yeah, damn, stupid me. Should have used string1 and string2, my bad! 🙈 Sorry!

Yeah, I guess this a non-issue then, a bit unexpected that the first run is that much slower, and would have guessed that timeit deallocates memory after a run (probably not that simple due to OS page caching)... I have to rethink my benchmark approach :)