sleep functions appears to slow over time

This will be tested more and I will post exact numbers and data later today but i figured might as well get the discussion rolling now and maybe someone can tell me whats going on…

so for awhile now I have been profiling everything in computercraft to see exactly what runs with what speeds and today I happened to look at loops at their bare minimum.

while true do
   for i=1,1000 do
      print(i)
   end
end

now assuming we are completely ignoring the standard yield time in computercraft I noticed each time it completes that for loop the next one will be a little bit faster. this seemed to cap out at about a .5 second difference going through the whole loop between the first and last times. This isn't too shocking since I am assuming lua must use some type of cache then to handle stuff like that. The really weird part is when you through sleep into the mix (mind you this is with no other computers on the single player world)

while true do
   for i=1,1000
      sleep(0.0)
   end
end

each loop this appeared to actually take longer to execute. roughly about a .00819 second difference from first to last test loop per sleep. the really weird part was when i broke out of multishell with term.redirect(term.native()). This actually Increased the amount it slowed down each loop these are the times for loops 1, 50, and 100

33.79999999996926
40.79999999996289
48.19999999995616

the 100th loop actually had NEARLY the same amount of time to execute as the last loop without redirecting out of multishell. can anyone actually explain what is going on here to help my further tests later today?


EDIT: I should clarify the time decrease in other functions such as .5 in print was almost immediate usually saving that by the second loop and staying the same during the test. Using sleep the time gradually increased with each loop run

That is because CraftOS runs on coroutines. When the event gets fired, exacty after 1 second or however long the sleep is, the event args get passed to all the coroutines. That consumes time.

Creator, on 17 May 2015 - 07:05 PM said:

That is because CraftOS runs on coroutines. When the event gets fired, exacty after 1 second or however long the sleep is, the event args get passed to all the coroutines. That consumes time.

I don't think you quite understood what I meant :P/> please reread what I said

The first loop sleeping 0.0 seconds 1000 times consumes roughly 34 seconds

The 100th loop again sleeping 0.0 seconds 1000 times consumes roughly 48 seconds

I know it takes time but the weird part is that it's gradually taking MORE time without adding more coroutines

Off the top of my head, I can tell you that every time you create a timer, its ID will be lastTimer + 1. It may be that Dan is using an array to store these timers, and isn't bothering to prune old indexes - instead building a new array and copying them all over every time the array fills up. This would lead to timer assignments causing a notable delay once for every, I dunno, every timer with an ID equal to a power of two or something? Getting twice as long each time it happens? That's just conjecture, but it'd fit the symptoms, I suppose. Try measuring every timer individually instead of in groups of 1000.

Exactly how are you doing your measurements, though? Your code snippets appear to be incomplete…

Another thing somewhat worth noting is that a timer won't fire its event until at least the next tick, on the tick. That is to say, sleep(0.0) == sleep(0.05). sleep(0.07) = sleep(0.1). etc.

Regarding your "print(i)" loop getting faster with each iteration, it's possible that "branch prediction" has something to do with that. Take a read through this.

Bomb Bloke, on 18 May 2015 - 12:45 AM said:

It may be that Dan is using an array to store these timers, and isn't bothering to prune old indexes - instead building a new array and copying them all over every time the array fills up.

Nope.

Take a look at my translation of terrible to read ComputerCraft code:

private Map<Integer, Timer> timerList;
private int nextTimerId = 0;

public void onTick(int ticksPassed) { // there is a chance of multiple having passed before this is called
  Iterator<Entry<Integer, Timer>>  timers = timerList.entrySet().iterator();

  while (timers.hasNext()) {
    Entry<Integer, Timer> entry = timers.next();
    Timer timer = entry.getValue();
    timer.delay -= (ticksPassed * 0.5d); // remove the passed time
    if (timer.delay <= 0.0d) {
      queueEvent("timer", entry.getKey());
      timers.remove();
    }
  }
}

public int createTimer(double delay)
  timerList.put(nextTimerId, new Timer(delay));
  return nextTimerId++;
end

private class Timer {
  public double delay;

  public Timer(double delay) {
    this.delay = delay;
  }
}

BIT's extract, plus my own observations with scripts that spam tons of timers, cements the idea that the delays you're seeing may have something to do with the manner in which you're measuring them.

Yes these are incomplete snippets sorry didn't think anyone wanted to see the profiler wrapping stuff. I am using pufferfish profiler which I have been told is as close as you can get to accurate being written in lua. It uses the debug API to poll times. I also made sure before each loop I completely reset the profiler to make sure it was doing the same readings with each loop

full snippet below

os.loadAPI("pufferfish")
for i=1,100 do
   local profiler = pufferfish.newProfiler()
   profiler:start()
   for t=1,1000 do
      sleep(0.0)
   end
   profiler:stop()
   outFile = io.open("results"..i,"w")
   profiler:report(outFile)
   outFile:close()
end

I've also tried moving the newProfiler outside of the loop and not resetting it and pretty much got the same exact results

Do you mean pepperfish? Testing an altered version of the mod (with access to the debug libraries) is asking for odd results, methinks.

The more I think about it the more things don't add up. Every sleep call has to wait for the next server tick to resolve, and given that there are no more than 20 server ticks per second, that means 1000 sleeps takes 50 seconds minimum. Even bearing in mind the odd precision error, that means your results are way too fast to be at all accurate.

Testing it myself reflected that:

local myFile = fs.open("results.txt","w")
for i=1,100 do
   local curTime = os.clock()
   for t=1,1000 do
      sleep(0)
   end
   myFile.writeLine(os.clock() - curTime)
end
myFile.close()

Spoiler

50.00000000000276
50.00000000001137
50.00000000001137
50.00000000001134
50.00000000001137
50.00000000001137
50.00000000001137
50.00000000001137
49.99999999997067
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
49.999999999954525
50.000000000180535
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819
50.0000000001819

oops yeah pepperfish >.> sorry wasn't home at the time so I was just writing stuff off the top of my head at best memory. And yes I knew I might get some awkward quirks from enabling debug but I figured it would be fewer quirks than if I had just ran it from an emulator. I'll test more today and try to figure out why sleep is giving me really really weird returns when all other functions seem to be profiler correctly…

It's possible that the time decreases (this was the result in some tests related to this), because your processor steps up, but increasing shouldn't be the case.