Extreme busy wait

[Shorttail]

I was trying out the Timer class, running an exact copy of the version in the doc: http://www.ponylang.org/ponyc/time-Timer/#timer

use "time"

actor Main
  new create(env: Env) =>
    let timers = Timers
    let timer = Timer(Notify(env), 5_000_000_000, 2_000_000_000)
    timers(consume timer)

class Notify is TimerNotify
  let _env: Env
  var _counter: U32 = 0
  new iso create(env: Env) =>
    _env = env
  fun ref apply(timer: Timer, count: U64): Bool =>
    _env.out.print(_counter.string())
    _counter = _counter + 1
    true

I expected cmd to output numbers every few seconds with little to no CPU utilization.

Cmd did display the numbers, but at 50% CPU utilization. When I ran the program from Git Bash (MinGW64) there was no output. I suspect the overhead of printing to the MinGW console was so high the busy waiting threads were completely starving out the writer.

I'm using Windows 7 64 bit, Intel i7-2630QM 2 GHz 4 core 8 thread CPU, 8 GB RAM.
$ ponyc -v
0.10.0-1c33065 [release]
compiled with: llvm 3.9.0 -- ?

[SeanTAllen]

The Git Bash problems are a known issue #1402.

@Shorttail could you try building from source and see if you get the same issue?

[SeanTAllen]

@kulibali do you have time to try this out and see if you get the same issue?

[chalcolith]

I'm running Windows 10, but I can confirm that this behaviour exists there as well. ponyc --version:

0.10.0-211e05d [release]
compiled with: llvm 3.9.1 -- msvc-14-x64

Compiling and running the timer program uses 50% of 8 CPU cores with cmd.exe, and doesn't print numbers in Git Bash.

[Shorttail]

Git Bash for Windows 7 doesn't use the WLS as far as I know, that's a feature for Windows 10 only.

[Shorttail]

I'm getting unresolved external symbol ponyint_pool_alloc_size, ponyint_hash_ptr, ponyint_pool_index when compiling. Both master and release say Windows build is failing. What branch should I try?

[chalcolith]

What version of Visual Studio are you using? What version of the Windows 10 SDK do you have installed?

[Shorttail]

Visual Studio Enterprise 2015 and Windows 10 SDK 10.1.14393.33.

[chalcolith]

Send me (gordon dot tisher at gmail dot com) the output of make configure && make -v on the master branch, please, and I'll try to see what is going on.

[chalcolith]

Thanks for sending me that output. The crucial error is:

LINK : warning LNK4044: unrecognized option '/WHOLEARCHIVE:libponyrt.lib'; ignored

It looks like you have a version of Visual Studio 2015 prior to Update 2, since the /WHOLEARCHIVE flag was only introduced to link.exe in Update 2. Can you update to the latest VS2015 and try again, please?

[Shorttail]

Installing update 3 helped and both debug and release build just fine.

The problem persists, however, and I still see 50% CPU utilization, both with the debug and release compiler:

0.10.0-1c4fef6 [release]
compiled with: llvm 3.9.1 -- msvc-14-x64

0.10.0-1c4fef6 [debug]
compiled with: llvm 3.9.1 -- msvc-14-x64

[SeanTAllen]

Thanks @Shorttail.

Does using the self compiled ponyc fix the Git Badh issue?

[Shorttail]

It does not fix Git Bash. However, lowering the repeat timer to 2 ms makes numbers get through sometimes.

I'm pretty sure I've observed this problem in programs written in other languages too, the layers of MinGW are a lot of overhead. I'm sure the output will show once the busy waiting is dealt with, Pony programs that actually terminate output just fine in Git Bash.

[Jonke]

Got the same issue, a unproportional high cpu load for this, on macOS Sierra

$ ponyc --version 0.11.0 [release] compiled with: llvm 3.9.1 -- Apple LLVM version 8.0.0 (clang-800.0.42.1)
$ bash --version GNU bash, version 3.2.57(1)-release (x86_64-apple-darwin16) Copyright (C) 2007 Free Software Foundation, Inc.

[SeanTAllen]

@Jonke did you compile ponyc yourself or did you get via homebrew?

[SeanTAllen]

@Shorttail @Jonke does either of you have time to do a "manual git bisect" and isolate the commit when the problem arises?

[Jonke]

@SeanTAllen with homebrew

[Jonke]

@SeanTAllen I'll try to make some time but what should be the good commit point?

[SeanTAllen]

honestly @Jonke i have no idea. when i have time, ill review commits and try to find some good places.

before you do that though, just try building from source to make sure you still have the issue.

also, thank you very much for helping.

[Jonke]

@SeanTAllen I built with every tag from 0.4 up to HEAD with both llvm 3.8 and 3.9 and could not see any difference with the timer example from the time package.

However it one changes the slop value it get a significant effect on the cpu usage, a slop = 1 gave me a cpu load 200%, a slop value =40 0.2% but then off course the timer don't work as expected.
The default slop = 20 ~25% cpu.

[SeanTAllen]

@Jonke what cpu do you have in your machine?

[Jonke]

@SeanTAllen 2,7 GHz Intel Core i5

[SeanTAllen]

How are you measuring cpu load @Jonke?

[Jonke]

@Shorttail top in terminal

[Shorttail]

If @Jonke sees a 25% default load on an i5 (4 cores, 4 threads, Pony should use 4 threads by default) in macOS, that's the timer busy waiting on a single thread. It is not the same issue as my 50% load in Windows (4 cores, 8 threads, Pony should use 4 threads), where every every thread in use busy waits. Granted, it's still a pretty big issue.

[Shorttail]

I ran the following echo server from the TCPListener documentation:

use "net"

class MyTCPConnectionNotify is TCPConnectionNotify
  fun ref received(conn: TCPConnection ref, data: Array[U8] iso): Bool =>
    conn.write(String.from_array(consume data))
    true

class MyTCPListenNotify is TCPListenNotify
  fun ref connected(listen: TCPListener ref): TCPConnectionNotify iso^ =>
    MyTCPConnectionNotify

actor Main
  new create(env: Env) =>
    try
      TCPListener(env.root as AmbientAuth,
        recover MyTCPListenNotify end, "", "8989")
    end

It runs by default at 50% load and with --ponythreads 8 it uses 100%.

I'll try building older versions of ponyc.

[Jonke]

@Shorttail your net example on my box seems to behave, i.e. it not uses 50% cpu flat out, more like idle round 0.2 %

pony version
0.11.1-c29443a [release]
compiled with: llvm 3.9.1 -- Apple LLVM version 8.0.0 (clang-800.0.42.1)

[Shorttail]

I ran Windows builds back to 0.2.2, the timer has 50% utilization in all of them. The echo server has that back to 0.10.0, before then the TCP part of the standard library is different and the code does not compile.

[SeanTAllen]

@Jonke we found a fix for the windows related issue of this. opening #1787 for your issue.