v1.22.0 Performance Issues

[Stephen Illingworth]

Hello,

I'm trying v1.22.0 and I'm measuring an approximate drop in performance of 10%. I'm comparing to v1.21.7

I'm looking at the release notes but I can't see anything that I would think would be having an impact. Is anyone else noticing a performance drop?

I've created a cpu.profile for my project for each the two go versions.

I can't see anything obviously different between the two profiles but then again, I'm not very skilled with pprof. I've uploaded them to github if anyone wants to help.

https://github.com/JetSetIlly/gopher2600_performance_profiles

Regards

Stephen

[Michael Knyszek]

Hey Stephen,

I poked at your profiles (diffing them) but my only guess is that it's a compiler change that's the culprit. (For future reference, I produced this output with the --diff_base flag, which subtracts one profile from another.)

Showing nodes accounting for -1.34s, 0.44% of 305.86s total
Dropped 4 nodes (cum <= 1.53s)
Showing top 20 nodes out of 248
      flat  flat%   sum%        cum   cum%
    -2.85s  0.93%  0.93%     -2.89s  0.94%  github.com/jetsetilly/gopher2600/hardware/tia/audio.(*Audio).Step
    -2.80s  0.92%  1.85%     -1.68s  0.55%  github.com/jetsetilly/gopher2600/hardware/tia.(*TIA).QuickStep
     1.52s   0.5%  1.35%      1.91s  0.62%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*Video).Pixel
     1.27s  0.42%  0.94%      2.04s  0.67%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*MissileSprite).tick
    -1.18s  0.39%  1.32%     -1.18s  0.39%  github.com/jetsetilly/gopher2600/hardware/memory/cartridge.(*Cartridge).AccessPassive (inline)
    -0.84s  0.27%  1.60%     -0.99s  0.32%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*PlayerSprite).tick
     0.67s  0.22%  1.38%      1.24s  0.41%  github.com/jetsetilly/gopher2600/hardware/cpu.(*CPU).read8Bit
     0.61s   0.2%  1.18%      1.46s  0.48%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*Video).Tick
    -0.54s  0.18%  1.35%     -0.59s  0.19%  github.com/jetsetilly/gopher2600/hardware/memory/cartridge.(*atari4k).Access
    -0.54s  0.18%  1.53%     -0.51s  0.17%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*PlayerSprite).pixel
     0.49s  0.16%  1.37%      0.49s  0.16%  github.com/jetsetilly/gopher2600/hardware/memory/memorymap.MapAddress (inline)
     0.47s  0.15%  1.22%      0.60s   0.2%  github.com/jetsetilly/gopher2600/hardware/memory/cartridge.(*Cartridge).Write (inline)
     0.47s  0.15%  1.06%      1.32s  0.43%  github.com/jetsetilly/gopher2600/hardware/riot/timer.(*Timer).Step
     0.41s  0.13%  0.93%      0.41s  0.13%  github.com/jetsetilly/gopher2600/hardware/memory/vcs.(*RIOTMemory).ChipRefer
     0.40s  0.13%   0.8%      0.44s  0.14%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*MissileSprite).pixel
     0.39s  0.13%  0.67%      0.39s  0.13%  github.com/jetsetilly/gopher2600/hardware/memory/vcs.(*RIOTMemory).ChipHasChanged
     0.36s  0.12%  0.55%      0.62s   0.2%  github.com/jetsetilly/gopher2600/hardware/riot/ports.(*Ports).Step
     0.35s  0.11%  0.44%      0.35s  0.11%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*BallSprite).pixel
    -0.33s  0.11%  0.55%     -0.59s  0.19%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*BallSprite).tick
     0.33s  0.11%  0.44%      0.85s  0.28%  github.com/jetsetilly/gopher2600/hardware/tia/video.(*MissileSprite).tickHMOVE

A couple questions just so we're on the same page:
- Are you certain these two profiles were produced from the same source code?
- Are you certain these two profiles represent the same amount of logical work being done? (As an example, in the context of a web service, I wouldn't want to measure 30s of traffic, but rather N identical requests handled to make an apples-to-apples comparison.)

If yes to both, then I think my conclusion is that this is probably the result of a compiler change, given that the flat time increases all seem to come from "user" code (as opposed to, say, runtime code).

Do you have a reproducer? It might be worth filing a GitHub issue at this point. (https://github.com/golang/go/issues/new/choose)

Thanks,
Michael

[Stephen Illingworth]

Hi Michael,

Thanks for looking at the profiles. I must confess that I didn't know about the --diff_base option. I'll take a closer look at the results of the diff and see if that can help me spot anything.

In answer to your questions: I'm certain these profiles were produced from the same source code and I'm also certain that the same amount of logical work was being done. I can rerun the tests and reproduce the results.

I'll raise an GitHub issue tomorrow if nothing else comes to light.

Thanks again

Stephen