[MLton-devel] streamIO

[Matthew Fluet]

> > I'm still curious about one anomaly.  With the old IO, I get:
> ...
> > <Posix_IO_read>    18.0% (14.46s) 18.0% (14.46s) 0.0%  (0.0s)
> ...
> > <Posix_IO_read>    25.5% (26.13s) 25.5% (26.13s) 0.0%  (0.0s)
> >
> > Now, the number of calls to Posix_IO_read and the arguments to it are the
> > same in both programs.  The only thing I can think of is that if the new
> > IO is just a little slower, then the difference in time between calls is
> > enough to cause a difference in the system call response (caching, paging,
> > etc.).
>
> Hopefully this anomaly is due to the problem with
> gcState.currentSource being cached in a register.  Let's try the
> benchmark again once that bug is fixed.

I reran this benchmark with the update to gcState.currentSource.  The
anomaly above remains.  (Makes sense, because the
gcState.currentSource/GCStateVolatile but only affected execution of code
in initGlobals.)

Old IO:
[fluet@cfs22 stable.time 7]% /usr/bin/time ./wc-scanStream 3000
45.68user 6.52system 0:52.25elapsed 99%CPU
[fluet@cfs22 stable.time 10]% mlprof -raw true -thresh 1 wc-scanStream mlmon.out
50.99 seconds of CPU time (1.18 seconds GC)
   function      cur    raw    stack   raw     GC    raw
--------------- ----- -------- ----- -------- ---- -------
loop            41.2% (21.50s) 78.5% (40.94s) 1.8% (0.95s)
sub             19.6% (10.20s) 19.6% (10.20s) 0.0%  (0.0s)
scanStream      18.7%  (9.75s) 97.2% (50.69s) 1.8% (0.95s)
<Posix_IO_read> 11.8%  (6.18s) 11.8%  (6.18s) 0.0%  (0.0s)
input1           5.4%  (2.83s) 37.2% (19.40s) 1.8% (0.95s)
<gc>             2.3%  (1.18s)  0.0%   (0.0s) 2.3% (1.18s)


New IO:
[fluet@cfs22 cvs.HEAD.time 5]% /usr/bin/time ./wc-scanStream 3000
66.57user 15.03system 1:21.63elapsed 99%CPU
[fluet@cfs22 cvs.HEAD.time 6]% mlprof -raw true -thresh 1 wc-scanStream mlmon.out
79.03 seconds of CPU time (2.52 seconds GC)
   function      cur    raw    stack   raw     GC    raw
--------------- ----- -------- ----- -------- ---- -------
input1          23.3% (18.98s) 59.1% (48.20s) 2.8% (2.29s)
loop            21.0% (17.14s) 80.1% (65.36s) 2.8% (2.29s)
<Posix_IO_read> 18.1% (14.78s) 18.1% (14.78s) 0.0%  (0.0s)
scanStream      16.2% (13.23s) 96.4% (78.60s) 2.8% (2.29s)
sub             12.5% (10.20s) 12.5% (10.20s) 0.0%  (0.0s)
sub              3.8%  (3.07s)  3.8%  (3.07s) 0.0%  (0.0s)
<gc>             3.1%  (2.52s)  0.0%   (0.0s) 3.1% (2.52s)
length           1.3%  (1.03s)  1.3%  (1.03s) 0.0%  (0.0s)


So, the program really is spending more time in system code with the new
IO than with the old IO.  So, my guess is that it really is a system
effect.  input1's time needs to be cut down a little (although I'm running
out of ideas), and hopefully more rapid calls to Posix_IO_read will
mitigate the system effect.



-------------------------------------------------------
This SF.net email is sponsored by: Scholarships for Techies!
Can't afford IT training? All 2003 ictp students receive scholarships.
Get hands-on training in Microsoft, Cisco, Sun, Linux/UNIX, and more.
www.ictp.com/training/sourceforge.asp
_______________________________________________
MLton-devel mailing list
MLton-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/mlton-devel