Ponyc: Extremely poor performance and high memory usage when iterating a FileLines instance

[andrewchambers]

Given the program:

use "files"

actor Main
  new create(env: Env) =>
    try
      var count: U32 = 0
      var path = FilePath(env.root as AmbientAuth, "./googlebooks-eng-all-1gram-20120701-0")?
      var file = OpenFile(path) as File
      for line in FileLines(file) do
        count = count + 1
      end
    end

Running on the data file https://storage.googleapis.com/books/ngrams/books/googlebooks-eng-all-1gram-20120701-0.gz (uncompress first)

You will see the program takes an extremely long time to iterate the file, moreover, the ram usage is more than I had expected: ~5GB from ~180 meg input file.

For comparison with python:

$ cat test.py
count = 0
for l in open("googlebooks-eng-all-1gram-20120701-0"):
    count += 1

$ time python test.py

real    0m2.092s
user    0m1.310s
sys     0m0.108s

$ time ./test-pony
<<Manually kill>>
real    0m18.638s
user    0m2.584s
sys 0m13.456s

Could reproduce with pony 0.18 on windows 10 and linux (xubuntu).

[SeanTAllen]

I'll look into this and make sure it isn't something beyond the expected "doing lots of work in a single behavior"

[andrewchambers]

Thanks, if I get time I'll try recursive behavior instead. My machine has 16 GB of ram so its not swapping or anything like that.

[andrewchambers]

Did some more looking, it seems in file.line() there is 1 syscall per byte read as there is no buffering during reading at all. Still not totally sure about the high memory usage though.

[SeanTAllen]

Python's next is doing some optimizations with a read-ahead buffer...

A file object is its own iterator, for example iter(f) returns f (unless f is closed). When a file is used as an iterator, typically in a for loop (for example, for line in f: print line.strip()), the next() method is called repeatedly. This method returns the next input line, or raises StopIteration when EOF is hit when the file is open for reading (behavior is undefined when the file is open for writing). In order to make a for loop the most efficient way of looping over the lines of a file (a very common operation), the next() method uses a hidden read-ahead buffer. As a consequence of using a read-ahead buffer, combining next() with other file methods (like readline()) does not work right. However, using seek() to reposition the file to an absolute position will flush the read-ahead buffer.

[SeanTAllen]

@andrewchambers take a queue from what you said and what python does (which is smart, read-ahead). I wrote a similar program:

use "buffered"
use "files"

actor Main
  new create(env: Env) =>
    try
      var count: U32 = 0
      var path = FilePath(env.root as AmbientAuth, "/Users/sean/Downloads/googlebooks-eng-all-1gram-20120701-0")?
      var file = OpenFile(path) as File
      let reader = Reader
      reader.append(file.read(file.size()))
      while true  do
        try
          reader.line()?
        else
          break
        end
        count = count + 1
      end
      env.out.print("Lines: " + count.string())
    end

time ./file-lines
Lines: 10512769
./file-lines  1.20s user 1.25s system 189% cpu 1.295 total

[SeanTAllen]

Also note that time for a pony program is going to include the time spent waiting for quiescence (aka the system to notice its ok to shutdown) so time isnt a good timing tool for pony programs.

[SeanTAllen]

File.line() reads 1 byte at a time. Very very slow. Definitely not so good for performance. I think we should move FileLines to using a buffer where it reads some or all of the file ahead of time and then we could discuss whether to make File.line() to do the same thing.

[andrewchambers]

Thank you - It could be argued FileLines should be doing the buffering considering it is what you want nearly all the time, and if you don't want it you can manually call File.line(). Though documentation changes or additions to the buffered class seem sensible too.

edit:

I missed your last post for some reason, totally agree.

[sylvanc]

This is very much a bug. There's no circumstance where reading one byte at a time is a good idea. This used to use _last_line_len to do predictive reading, and handle buffering inside of File, and should go back to doing that. Good catch, @andrewchambers .

[SeanTAllen]

@sylvanc so previously we used fgets_unlocked which will read up to X characters but stop at a newline. If we continue to use the lower-level vectored code that we switched to in:

https://github.com/ponylang/ponyc/commit/35094a751750f12b36e817a5818433aa5026407b

that isn't possible. We should talk about the approach we want to take here. If we use read and read ahead, we are going to have to manage the file position so that people don't get unusual surprises when the get a line then do some other non-line operations.

additionally, i think it makes sense for FileLines to use a Reader and buffer all or most of the file in one go.

ive come up with multiple approach and they are all fraught with issue.

[andrewchambers]

I think anything that requires buffering could be done through the buffered package to follow least surprise. If File was changed to be unbuffered intentionally, the line() method probably shouldn't be there.

[allyraza]

I am not a pony user just been looking into the source code of runtime, I have experience with erlang though. I would say avoid the loops in actors high memory could be because of the gc is not collecting and waiting for the actor to end at least that is what happens in erlang, you should handle iterations with timers, there is a timer module in erlang I am not sure if pony has timer concept.

[andrewchambers]

Yes, the reason is the loops, but the question to ask, is why does a 180 meg file balloon to 5 Gigs of ram, I would hope it could be handled in 300-600 megs even if doing it in a stupid way.

[SeanTAllen]

@andrewchambers if you look at line() in File, you'll see it reserves memory for lines. These in turn will potentially grab larger chunks than are needed (this is usually a good thing) which is going to end up allocating larger than the 180 as it is streaming along try to guess the correct amount to allocate. Allocating a byte at a time as it reads would be even slower. Take a look inside Array for how it allocates based on powers of 2.

[SeanTAllen]

We have decided to go with the following approach:

1) remove line() from File as it is surprisingly slow and its existence could end up biting people.
2) update documentation to tell people to use FileLines
3) audit File for other performance issues that might have come about when we switch from c style handles to using file descriptors with writev()
4) make the following changes to FileLines:

• use buffered.Reader to store data
• keep track of the position we have read up to
• when it is time to "refill" our buffer:
  
  
  
  • determine current seek position of the underlying file, save that so we can restore later
  
  
  • move the seek position to last point that our buffer read to
  
  
  • read more data
  
  
  • store where we read to for next time we need to "refill our buffer"
  
  
  • reset file to seek position it was at before we started reading.
  
  

[jkleiser]

I have tried a slightly modified version of examples/files/files.pony like this:

use "files"

actor Main
  new create(env: Env) =>
    let caps = recover val FileCaps.>set(FileRead).>set(FileStat) end

    try
      with file = OpenFile(
        FilePath(env.root as AmbientAuth, env.args(1)?, caps)?) as File
      do
        env.out.print(file.path.path)
        for line in file.lines() do
          try
            let pos: ISize = line.find("mandag")?
            env.out.print(pos.string() + ": " + line)
          end
        end
      end
    else
      try
        env.out.print("Couldn't open " + env.args(1)?)
      end
    end

and I ran it on one of the "not so big" text files (.vec) found here:
https://github.com/facebookresearch/fastText/blob/master/pretrained-vectors.md
The "Norwegian (Bokmål)" .vec file is 1.35 GB, containing 515788 lines.
When I did time ./files path-to/wiki.no.vec, it took more than 8 minutes to complete on my Mac:

real    10m33.570s
user    1m50.525s
sys 8m52.714s

I used ponyc 0.19.2-a377924.
Is it possible to speed this up significantly without doing too much low level stuff?
I'm looking for an execution time closer to 30 seconds.

[SeanTAllen]

@jkleiser yes, see my comment from August 22nd about using Reader from the buffered package.

[jkleiser]

Thanks, @SeanTAllen . Using Reader speeds up execution significantly. My code now looks like this:

use "buffered"
use "files"

actor Main
  new create(env: Env) =>
    let caps = recover val FileCaps.>set(FileRead).>set(FileStat) end
    try
      let path = FilePath(env.root as AmbientAuth, env.args(1)?, caps)?
      let file = OpenFile(path) as File
      let reader = Reader
      var count: U32 = 0
      reader.append(file.read(file.size()))
      while true  do
        try
          let line = reader.line()?
          try
            let pos: ISize = line.find("mandag")?
            env.out.print(pos.string() + ": " + line)
          end
        else
          break
        end
        count = count + 1
      end
      env.out.print("Lines: " + count.string())
    end

The times reported are now really nice:

real    0m8.288s
user    0m4.539s
sys 0m4.218s

[jkleiser]

Yes, using Reader speeds up execution, but I now have problems with memory usage. My code has evolved a little; now every line read is split_by(" "), and in the first line I expect to find two unsigned integers (as in a .vec file). When the last line is read, it prints out the number of lines and the time used. When I run this on the big .vec file (1.35 GB) I mentioned earlier, it takes some 30 secs before it prints "Lines read" and "Time used", but I don't get the shell prompt back (for a long while). When I look in the Activity Monitor on my Mac, I see it's still using CPU, and it actually peeks after some 70-80 secs later and then goes down again. According to Activity Monitor it now uses 17.3 GB of memory! This is my code:

use "buffered"
use "files"
use "time"

actor Main
  new create(env: Env) =>
    let caps = recover val FileCaps.>set(FileRead).>set(FileStat) end
    try
      let path = FilePath(env.root as AmbientAuth, env.args(1)?, caps)?
      let file = OpenFile(path) as File
      let reader = Reader
      var line_number: U32 = 0
      reader.append(file.read(file.size()))

      Time.perf_begin()
      let start = Time.micros()

      while true do
        try
          let line = reader.line()?
          let parts = line.split_by(" ")
          line_number = line_number + 1
          if line_number == 1 then
            try
              let word_lines = parts(0)?.u32()?
              let dims = parts(1)?.u32()?
              env.out.print("word_lines=" + word_lines.string() + ", dims=" + dims.string())
            else
              env.err.print("*** Could not read numbers from line 1")
              break
            end
          end
          try
            let pos: ISize = line.find("shetlandsponni")?
            env.out.print(line_number.string() + ": " + line + "\n")
          end
        else
          break
        end
      end

      let stop = Time.micros()
      Time.perf_end()
      env.out.print("Lines read: " + line_number.string()
                + ", Time used: " + (stop - start).string() + " micros")
      file.dispose()
    end

If you'd like to test this without having to download the 1.35 GB file, you can generate a (286.9 MB) test file using this shell script:

for i in {1..9000000}; do printf '%d 123 456 789 123 456 789\n' "$i"; done >bigfile.txt

To see a really long delay after the "Lines read" and "Time used" are printed, however, you should make that test file at least twice as big, I think.

[SeanTAllen]

Yes, you are doing everything in a single behavior call so gc isn't run. What you would want to do is have another behavior for handling each line. When you read in a line, send it off the other behavior and keep processing. That will deal with garbage recreated by non-file reading. Its quite possible you will need to break up the file reading where you doing something like:

Read 100 lines, call a behavior stop queue up more file reading, exist your file reading behavior.

This:

1) Frees up the scheduler to do other things than just read the file
2) Allows any file reading garbage recreated to be gc'd between calls.

TCPConnection does this with its _read_again behaviour.

[jkleiser]

Thanks, @SeanTAllen. I'll try what you suggest, but it will probably have to wait a week or so. ;-)

[jemc]

@jkleiser - Also note that we have String methods like trim that allow you to "share" an underlying byte buffer among multiple String val objects without copying. Depending on what you're doing, this may be more appropriate than using split_by.

It's a double-edged sword - if you intend to keep all or most of the buffer around in your split chunks, then trim would probably be a good choice because they can all share the same underlying 1.3 GB buffer with no copying. If you only intend to hold on to small portions of the large buffer, then trim may not be a good choice, because holding onto a String val that is just a few bytes long but was trimmed from the large buffer will hold onto the entire large buffer internally.

[jkleiser]

I have now come up with a solution to my big-file reader problem that performs very well, thanks to hints that I got here. My solution now allows the reading to be aborted if some condition is satisfied. Here it is:

use "buffered"
use "files"
use "time"

actor Main
  let _env: Env
  let _start: U64
  var _line_number: U32 = 0
  var _done_reading: Bool = false

  new create(env: Env) =>
    _env = env
    Time.perf_begin()
    _start = Time.micros()

    let caps = recover val FileCaps.>set(FileRead).>set(FileStat) end
    try
      let path = FilePath(_env.root as AmbientAuth, _env.args(1)?, caps)?
      let file = OpenFile(path) as File
      let reader = Reader
      reader.append(file.read(file.size()))

      _read_more(consume reader)
    end

  be _read_more(reader: Reader iso) =>
    if not _done_reading then
      try
        let line = reader.line()?
        _line_number = _line_number + 1
        _handle_line(line)?
        _read_more(consume reader)
      else
        _finish()
      end
    end

  fun _handle_line(line: String) ? =>
    let parts = line.split_by(" ")
    if _line_number == 1 then
      try
        let word_lines = parts(0)?.u32()?
        let dims = parts(1)?.u32()?
        _env.out.print("word_lines=" + word_lines.string() + ", dims=" + dims.string())
      else
        _env.err.print("*** Could not read numbers from line 1")
        error
      end
    else
      try
        let pos: ISize = line.find("shetlandsponni")?
        _env.out.print(_line_number.string() + ": " + line + "\n")
      end
    end

  fun ref _finish() =>
    _done_reading = true
    let stop = Time.micros()
    Time.perf_end()
    _env.out.print("Lines read: " + _line_number.string()
                + ", Time used: " + (stop - _start).string() + " micros")

Let me know if you spot things that should be done smarter. ;-)

[andrewchambers]

@jkleiser please send your questions to the irc channel and not this github issue.

[SeanTAllen]

@mfelsche is #2707 intended to close this issue?

[mfelsche]

Indeed