Strange performance boost for calling a proc defined twice

ID:2232012
 
Apr 3 2017, 9:57 pm
Code:
/datum/profile
    var/iterations = 1e4

    proc/profile1(a)
        return a++

    proc/profile2(a)
    profile2(a)
        return a++

client/verb/profile()
    set background = 1

    var/datum/profile/p = new
    for(var/i in 1 to p.iterations)
        world << "[(i/p.iterations)*100]% complete."
        . += p.profile1(.)
        . += p.profile2(.)




Can anyone explain why profile2 appears to be a lot cheaper to call when defined in this manner? Someone posted this on our github and I just can't explain it or figure out why it would be.
Apr 4 2017, 5:32 am
What changes if you remove the set background?
Apr 4 2017, 6:34 am
Did you consider the possibility that only proc/profile2() the empty proc is being called since there is no super call?
Apr 4 2017, 9:29 am
In response to Laser50
It triggers the infinite loop check.
Apr 4 2017, 9:30 am
In response to Clusterfack
No, this is not what happens. It calls with the correct functionality as the post indicates. This is how most functions in tg's gas_mixture.dm are defined.
Apr 4 2017, 10:08 am
What I find bizarre is that the proc path comes through without the "proc" keyword in it. That's odd. It's still a proc after all. Maybe that's been happening with overridden procs right along, but this is the first I've noticed it. I'm not sure that's good, especially considering text2path() looks for the proc and verb keywords.

If you reverse the call order, do you get the same results?
Apr 4 2017, 10:25 am
In response to Lummox JR
This is normal. What's happening is that the latest-defined (in terms of compilation order) proc is called, which is normal. If/when that proc calls ..(), then the next-latest proc is called (whether it's in the same type or a parent type). Every such proc appears as a separate entry in the profiler. (It would be nice if the profiler included filename and line number for this reason...)

So, since the override doesn't call ..(), it's the only one that appears; and the path to it doesn't include "proc" because that's how overrides appear in the code tree.

This doesn't explain the reported performance difference, though.
Apr 4 2017, 12:41 pm
In response to Kaiochao
It seems to me, though, that overrides not including /proc might be considered a bug.
Apr 4 2017, 2:49 pm
In response to Dunc
No, this is not what happens. It calls with the correct functionality as the post indicates.

But the post doesn't indicate that though?
Apr 4 2017, 3:51 pm
https://pastebin.com/5RTqKMuX

Some more results of testing are now showing that no benefit appears to be occuring, so the original profile is even stranger.
Apr 4 2017, 4:00 pm
http://i.imgur.com/YX7jStr.png

This seems definitive, there is no performance increase, I have nothing to explain the original result
Apr 4 2017, 4:48 pm
the definitive test:

https://pastebin.com/YBqG4Etv

i don't have a profile open for it, but it shows the same thing, about the same performance
Apr 4 2017, 7:12 pm
I'd like to note that the snippet in the OP didn't produce anywhere near as dramatic of a difference on my machine as it did on OP's.

Here, it was a .001 difference between the two calls at max, and it went back-and-forth as to which one was that much faster.
Apr 4 2017, 9:41 pm
There was some theorycrafting that it was simply due to being called second and some kind of warmup for the byond language VM
Apr 5 2017, 12:27 pm
Hopes were born and destroyed in a single thread, I couldn't reproduce it either.

The first post's profiling results almost made me go into shock lol.
Apr 5 2017, 11:15 pm
So, new anecdotal evidence has come up suggesting it might actually be faster:


https://github.com/tgstation/tgstation/pull/25897

72 seconds to initialize /tg/ ss13 vs 85 seconds.
Apr 5 2017, 11:44 pm
How many times was this test run
Apr 5 2017, 11:46 pm
Read the pr?

That one was just once, but there was another series of tests mentioned in the pr that did it 3 times and got the same result all 3 times.
Apr 6 2017, 10:20 am
Weird. To make any headway on this I think we need a simple case like the original post that can demonstrate the issue, but on a more consistent basis.
Apr 6 2017, 3:19 pm
MSO his pr wasn't even initialising lighting objects.