run-time segfault on clumsy dining philosophers program

[dimmie]

Hello Ponies !

New to pony and still not quite at ease with the many new concepts. Anyway, I tried myself at the dining philosophers problem and got at last my code compiled. The program sort of works, but usually silently exits after a few dozen iterations. In the more useful cases, it segfaults - which this is about.

ponyc is compiled from fresh git sources ($ ./ponyc-debug -v : 0.2.1-59-ge640645). The documentation includes $ tar -tzf philo-core.tgz philo1 philo/main.pony philo1.log core

The segfault was more or less reproducible when running ./philo1 -v

The philosophers eat then work and turn back to eat. Scheduling is controlled by grabbing both forks at once (a bit "ring" of forks keeps track of forks usage) and working philosophers are registered in a "busy" bit array.

It is quite possible that the problems I experience arise from my lack of experience in pony or otherwise - in that case, kindly point out where my errors and msiconceptions lie.

Thanks for any help - pony is going to be a great language. Only the documentation is a bit lacking at the moment.

-rg-

P.S. If interested, tell me where to send the 1MB philo-core.tgz tar file, whilch github refuses to upload.

[andymcn]

Thanks for letting us know you're having problems. Whatever you may be doing wrong in your code you shouldn't be able to make a Pony program segfault, so it's probably our fault.

Will github let you upload just your Pony source file? That would be a very good start to working out what's going on.

[dimmie]

Thanks for answering so promptly !

The upload is a tar.gz file uploaded after appending a .jpg extension. Is it usable ?

[andymcn]

Yes, that's usable, thanks. Having to rename the file to be a jpg to upload is very silly of github, but it's a good trick to note for next time.

From your source I can reproduce the segfault. I shall investigate!

[dimmie]

;))

[andymcn]

This appears to be a good old fashioned "we're putting the wrong value somewhere" in the GC code, so @sylvanc can you have a look at it please.

The problem is that the actor field in an actorref_t is being set to 0x1_0000_0001 (or occasionally NULL). I do not think that this is a random memory stomp as it is far too consistent and I can reproduce it on both Windows and Linux (not tried on OSX). I assume therefore that this is something going off the end of a list, casting to the wrong type, or similar.

The stack trace I get when this happens is:

#3  0x00007ffff6f0ee42 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#4  0x000000000041636e in has_flag ()
#5  0x00000000004168d6 in actor_pendingdestroy ()
#6  0x000000000041f537 in send_release ()
#7  0x000000000041f6aa in actormap_sweep ()
#8  0x000000000041a74e in gc_sweep ()
#9  0x00000000004165e5 in try_gc ()
#10 0x00000000004166fa in actor_run ()

In actormap_sweep() (frame 7) before the call to send_release(), aref->actor is already the bad value.

For reference here is the example program that provokes the error. I've not tried shortening it yet.

use "options"
use "time"
use "collections"
use "random"

//use @usleep[U32](usecs :U32)

class Config
  var count: U64 = 5
  var scale: U64 = 100
  var debug: Bool = false
  var usleep: Bool = false
  var verbose: Bool = false

  fun ref apply(env: Env): Bool =>
    var options = Options(env)

    options
      .add("count", "c", I64Argument)
      .add("scale", "s", I64Argument)
      .add("debug", "d", None)
      .add("usleep", "u", None)
      .add("verbose", "v", None)

    for option in options do
      match option
      | ("count", var arg: I64) => count = arg.u64()
      | ("scale", var arg: I64) => scale = arg.u64()
      | ("debug", var arg: None) => debug = true
      | ("usleep", var arg: None) => usleep = true
      | ("verbose", var arg: None) => verbose = true
      | let err: ParseError =>
        err.report(env.out)
        env.out.print(
          """
          philo [OPTIONS]
            --count    -c   number of philosophers
            --scale    -s   waiting units (ms)
            --debug    -d   enable debug output on stdout
            --usleep   -u   use usleep instead of Timers
            --verbose  -v   list main actions on stdout
          """
          )
        return false
      end
    end

   if debug then 
      env.out.print(
        "count: " + count.string()
        )
   end
    true

class TimerWatch is TimerNotify
  """
     from example/timers
  """
  let _env: Env
  let _params: Params val
  let _debug: Bool
  let _logger: Logger
  var _count: U64 = 0
  let _caller: Guest
  let _id: U64

/*
  new iso create(env: Env) =>
    _env = env
*/

  new iso assign(env: Env, params: Params val, caller: Guest, id: U64) =>
    _env = env
    _params = params
    _debug = _params.debug
    _logger = _params.logger
    _caller = caller
    _id = id
    if _debug then
      _logger.message("# timer assigned id: " + _id.string())
    end

  fun ref apply(timer: Timer, count: U64): Bool =>
    _count = _count + count
    if _debug then
      _logger.message("# timer elapsed id: " + _id.string() +
                      " count: " + _count.string())
    end
    // break after that many cycles
    _count < 1

  fun ref cancel(timer: Timer) =>
    if _debug then
      _logger.message("# timer cancelled id: " + _id.string())
    end
    _caller.proceed(_id)

class Microsleep

  new create () => this

  fun udeep(usecs': U64) :U32 =>
    let usecs: U32 = usecs'.u32()
    let ret = U32(0) //@usleep(usecs)
    ret

actor Guest
  let _env: Env
  let _debug: Bool
  let _usleep: Bool
  let _verbose: Bool
  let _scale: U64
  var _main: Main
  let _params: Params val
  let _logger: Logger
  let _id: U64
  var _state: U64
  var _dispose: Bool = false
  var _eating: U64
  var _working: U64
  var _rand: Random
  let _timers: Timers
  let _snooze: Microsleep

  new create(env: Env, params: Params val, main: Main, id': U64) =>
    var seed: U64 = 9876543
    _main = main
    _env = env
    _params = params
    _debug = _params.debug
    _usleep = _params.usleep
    _verbose = _params.verbose
    _scale = _params.scale
    _logger = _params.logger
    _id =id'; _state = 0
    _rand = MT()
    for i in Range[U64](0, id' + 1) do
      seed = 12345 + _rand.int(54321)
      _rand = MT(seed)
    end
    // microseconds version, for Microsleep
    _snooze = Microsleep
    _timers = Timers.create()
    if _usleep then
      _eating = (_scale + _rand.int(3 * _scale)) * 1000
      _working = (_scale + _rand.int(7 * _scale)) * 1000
    else
      // nanoseconds version, for pony timers
      _eating = (_scale + _rand.int(3 * _scale)) * 1000000
      _working = (_scale + _rand.int(7 * _scale)) * 1000000
    end

  fun getId() :U64 => _id

  be proceed(id: U64) =>
    if _debug then
      _logger.message("# proceed " + _id.string() +
                      " (state: " + _state.string() + ")")
    end
    if _state == 2 then
      _state = 1; _main.situp(_id)
    else
      _state = 0; _main.clear(_id)
    end
    _main.schedule()

  be eat() =>
    if _usleep then
      _snooze.udeep(_eating)
    else
      // if (_dispose = _dispose or true) then _timers.dispose() end
      let timer = Timer(TimerWatch.assign(_env, _params, this, _id),
                         _eating, _eating)
      _timers.apply(consume timer)
    end
    _state = 2
    if _verbose then
      _logger.message(_id.string() + ": eating (" + _eating.string() + ")")
    end

  be work() =>
    if _usleep then
      _snooze.udeep(_working)
    else
      // if (_dispose = _dispose or true) then _timers.dispose() end
      let timer = Timer(TimerWatch.assign(_env, _params, this, _id),
                         _working, _working)
      _timers.apply(consume timer)
    end
    _state = 1
    if _verbose then
      _logger.message(_id.string() + ": working (" + _working.string() + ")")
    end

class Params
  let debug: Bool
  let usleep: Bool
  let verbose: Bool
  let scale: U64
  let logger: Logger

  new val create(debug': Bool, usleep': Bool, verbose': Bool,
                 scale': U64, logger': Logger) =>
    debug = debug'
    usleep = usleep'
    verbose = verbose'
    scale = scale'
    logger = logger'

actor Logger
  let _env: Env

  new create(env: Env) =>
    _env = env

  be message(text: String) =>
    _env.out.print(text)

actor Main
  let _env: Env
  var _config: Config = Config
  let _params: Params val
  let _logger: Logger
  let _debug: Bool
  let _usleep: Bool
  let _verbose: Bool
  var _table: U64 = 0
  var _busy: U64 = 0
  var _forks: U64 = 0b11
  let _gcount: U64
  let _gforks: Array[U64]
  let _gbusy: Array[U64]
  var _guests: Array[Guest]
  let _snooze: Microsleep = Microsleep
  var _kick: U64 = 0

  var _last: U64 = 0

  new create(env: Env) =>
    _env = env

    if _config(env) then
      _debug = _config.debug
      _usleep = _config.usleep
      _verbose = _config.verbose
      _logger = Logger(_env)
      _params =
        Params(_debug, _usleep, _verbose, _config.scale, _logger)
      var guest: U64 = 1
      let guest_count = _config.count
      let guests = recover Array[Guest](guest_count) end
      let guest_forks = recover Array[U64](guest_count) end
      let guest_busy = recover Array[U64](guest_count) end

      for i in Range[U64](0, guest_count) do
        guests.push(Guest(_env, _params, this, i))
        guest_forks.push(_forks); _forks = _forks << 1
        guest_busy.push(guest); guest = guest << 1
      end
      try
        guest_forks(guest_count - 1) =
          guest_forks(guest_count - 1) xor (guest or 1)
      end

      _gcount = consume guest_count
      _gforks = consume guest_forks
      _gbusy  = consume guest_busy
      _guests = consume guests

    else
      _logger = Logger(_env)
      _params = Params(false, false, false, 0, _logger)
      _debug = false
      _usleep = false
      _verbose = false
      _gcount = 0
      _gforks = recover Array[U64](1) end
      _gbusy = recover Array[U64](1) end
      _guests = recover Array[Guest](1) end
    end

    if _verbose or _debug then
      try
        for i in Range[U64](0, _gcount) do
          _logger.message("guest " + i.string() + 
            " forks: " + binary(_gforks(i), _gcount) +
            " busy: " + binary(_gbusy(i), _gcount)
          )
        end
      end
    end
    if _usleep then
      _logger.message("timed by usleep timers")
    else
      _logger.message("timed by pony timers")
    end

    schedule()
//  for_ever()

  fun for_ever() =>
    repeat 
      schedule()
      _snooze.udeep(2500000)
    until false end

  be situp(id: U64) =>
    try 
      _table = _table and not _gforks(id)
    else
      _logger.message("!!! situp failed: " + id.string())
      // error
    end
    if _verbose then
      _logger.message("Has Eaten: " + id.string())
    end
    try
      _guests(id).work()
    else
      _logger.message("!!! _guests(" + id.string() + ").work failed: ")
    end

  be clear(id: U64) =>
    try 
      // _table = _table and not _gforks(id)
      _busy = _busy and not _gbusy(id)
    else
      _logger.message("!!! clear failed: " + id.string())
      // error
    end
    if _verbose then
      _logger.message("Back again: " + id.string())
    end

  be schedule() =>
    var cnt: U64 = 0
    var i = _last

    if _verbose then print_state(">Schedule: ", _last, _table, _busy) end

    _kick = 0
//  repeat
    while cnt < _gcount do
      try
        if ((_table and _gforks(i)) == 0) and
           ((_busy and _gbusy(i)) == 0)
        then
          _kick = _kick + 1
          _table = _table or _gforks(i)
          _busy = _busy or _gbusy(i)
          _guests(i).eat()
          if _verbose then
            _logger.message("Eating: " + i.string() )
          end
        end
      else
        _logger.message("!!! schedule failed: " + i.string())
        // error
      end
      i = i + 1
      if i >= _gcount then 
        i = 0
      end
      cnt = cnt + 1
    end
    _last = i
    if _kick == 0 then _snooze.udeep(250000) end
//  until _kick > 1 end

    if _verbose then print_state("<Schedule: ",_last, _table, _busy) end

  fun print_state(head: String, last: U64, table: U64, busy: U64) =>
    _logger.message(head + "- last: " + last.string() +
                   " forks: " + binary(table, _gcount) +
                   " guests: " + binary(busy, _gcount))

  fun binary(arg: U64, width: U64) :String ref =>
    var mod: U64 = 0
    var bin = String(width)
    var rst: U64 = arg
    var itr: U64 = 0

    while itr < width do
      if rst > 0 then
        mod = rst % 2; rst = rst / 2
        bin.append(if mod == 0 then "0" else "1" end)
      else 
        bin.append("0")
      end
      itr = itr + 1
    end
    bin

[sylvanc]

Just an update that I'm still working on this. It's the same bug as #320.

[andymcn]

We believe this is now fixed. We never actually pinned down exactly what was going wrong, but we've fixed a number of minor issues relating to memory handling and now we cannot reproduce this anymore.

Closing the issue. If anyone can still reproduce it please reopen with details of what you're doing and seeing.

[hakvroot]

Coincidentally I also decided to give Pony a try by writing a dining philosophers version and hit the memory issue (as described in https://github.com/CausalityLtd/ponyc/issues/320) as well. At that time I was using ponyc 0.2.1 and decided to compile with the latest version 0.2.1-405-g60e05ac to migitate this issue.

In using 0.2.1-405-g60e05ac I found my version of the dining philosophers to be more unstable. Sometimes my philosophers manage to satisfy their appetites, but usually the program segfaults before completion. In one instance I got an assertion failure :

pony: src/libponyrt/mem/pool.c:598: pool_free: Assertion `index < (20 - 5 + 1)' failed.

My version of the dining philosophers can be found at https://gist.github.com/hakvroot/9fadf8572988eab1c300.

Regarding the code : the count (amount of philosophers) and appetite (amount of iterations before a philosopher stops dining) constants can be changed to increase pressure on actor count or runtime duration respectively. The program itself deadlock free, but not livelock free.

Other than that it might also be interesting to know I'm running Linux Mint 17.1 with LLVM version 3.6.2 and that writing Pony is pretty fun! If there is any more information I can provide, let me know :)