[Mono-list] Fwd: Threading and IO problem

Yanko Hernández Álvarez yhdezalvarez at gmail.com
Fri Mar 7 13:45:32 EST 2008


On Fri, Mar 7, 2008 at 10:32 AM, Paolo Molaro <lupus at ximian.com> wrote:
> On 03/07/08 Yanko Hernández Álvarez wrote:
>  > Ok, then there is one question left: is there any way to program this
>  > using threads without the GC interfering? any ideas?
>
>  It looks like the GC needs a little manual tuning for your app.
>  For a 600 MB file on a dual core with 2 threads running a good
>  default seems to be setting an initial heap size of 10 MB:
>         GC_INITIAL_HEAP_SIZE=10000000 mono yourprog.exe
>  With 4 threads (which is sort of equivalent to 8 threads on a 4 cpu
>  hyperthreaded box) you need about 20 MB, but try also with more
>  and measure what's best for your workload (and please report back your
>  results).

# time ./program.exe example.log
real	1m3.233s
user	4m55.657s
sys	0m51.567s
# (./program.exe example.log &); top -b | grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 61.6%us,  8.8%sy,  0.0%ni, 29.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 58.6%us, 11.7%sy,  0.0%ni, 29.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 57.4%us, 10.1%sy,  0.0%ni, 32.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 60.8%us,  9.2%sy,  0.0%ni, 30.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 57.4%us,  9.8%sy,  0.0%ni, 32.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 59.8%us,  9.6%sy,  0.0%ni, 30.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 58.6%us, 11.5%sy,  0.0%ni, 29.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 60.3%us, 10.2%sy,  0.0%ni, 29.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 63.0%us,  9.6%sy,  0.0%ni, 27.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 62.2%us, 10.2%sy,  0.0%ni, 27.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 62.3%us,  9.7%sy,  0.0%ni, 28.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 59.9%us, 10.1%sy,  0.0%ni, 30.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 57.4%us,  9.2%sy,  0.0%ni, 33.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 59.3%us,  9.2%sy,  0.0%ni, 31.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 57.7%us,  9.4%sy,  0.0%ni, 32.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 60.7%us,  9.1%sy,  0.0%ni, 30.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 60.7%us,  8.8%sy,  0.0%ni, 30.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 57.2%us,  9.2%sy,  0.0%ni, 33.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 48.7%us,  5.8%sy,  0.0%ni, 45.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 29.6%us,  2.3%sy,  0.0%ni, 68.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 27.6%us,  1.6%sy,  0.0%ni, 70.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 10.5%us,  0.9%sy,  0.0%ni, 88.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.8%us,  0.1%sy,  0.0%ni, 99.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~30%
-----------
# time GC_INITIAL_HEAP_SIZE=10485760 ./program.exe example.log
real	0m51.897s
user	4m42.115s
sys	0m43.071s

# (GC_INITIAL_HEAP_SIZE=10485760 ./program.exe example.log &); top -b
| grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 67.6%us, 12.5%sy,  0.0%ni, 19.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 68.4%us, 12.4%sy,  0.0%ni, 19.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 70.5%us, 11.1%sy,  0.0%ni, 18.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 69.0%us, 11.5%sy,  0.0%ni, 19.5%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Cpu(s): 69.3%us,  9.6%sy,  0.0%ni, 21.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 70.7%us, 10.4%sy,  0.0%ni, 18.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 70.6%us, 10.2%sy,  0.0%ni, 19.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 71.5%us,  9.6%sy,  0.0%ni, 18.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 71.9%us,  9.9%sy,  0.0%ni, 18.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 70.9%us, 10.3%sy,  0.0%ni, 18.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 71.4%us,  9.1%sy,  0.0%ni, 19.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 68.4%us, 10.3%sy,  0.0%ni, 21.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 68.4%us,  9.7%sy,  0.0%ni, 21.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 71.7%us,  9.4%sy,  0.0%ni, 18.8%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Cpu(s): 60.1%us,  6.9%sy,  0.0%ni, 33.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 29.1%us,  1.3%sy,  0.0%ni, 69.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 24.0%us,  0.9%sy,  0.0%ni, 75.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  4.0%us,  0.5%sy,  0.0%ni, 95.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.9%us,  0.1%sy,  0.0%ni, 99.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~20%
-----------
# time GC_INITIAL_HEAP_SIZE=20971520 ./program.exe example.log
real	0m51.010s
user	4m45.998s
sys	0m35.541s

(GC_INITIAL_HEAP_SIZE=20971520 ./program.exe example.log &); top -b |
grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.1%us,  9.0%sy,  0.0%ni, 13.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 74.3%us, 11.1%sy,  0.0%ni, 14.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.3%us,  8.4%sy,  0.0%ni, 13.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.0%us,  9.2%sy,  0.0%ni, 14.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 79.0%us,  7.2%sy,  0.0%ni, 13.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.3%us,  9.0%sy,  0.0%ni, 14.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.6%us,  8.9%sy,  0.0%ni, 13.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 75.8%us,  8.7%sy,  0.0%ni, 15.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.4%us,  8.9%sy,  0.0%ni, 14.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.5%us,  7.6%sy,  0.0%ni, 13.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.6%us,  9.1%sy,  0.0%ni, 14.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 75.9%us,  9.3%sy,  0.0%ni, 14.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.9%us,  7.8%sy,  0.0%ni, 15.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 72.5%us,  7.0%sy,  0.0%ni, 20.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 60.9%us,  3.9%sy,  0.0%ni, 35.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 44.3%us,  2.0%sy,  0.0%ni, 53.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 29.7%us,  1.5%sy,  0.0%ni, 68.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.4%us,  0.0%sy,  0.0%ni, 99.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~14%
-----------
# time GC_INITIAL_HEAP_SIZE=52428800 ./program.exe example.log
real	0m50.480s
user	4m53.144s
sys	0m39.427s
# (GC_INITIAL_HEAP_SIZE=52428800 ./program.exe example.log &); top -b
| grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.2%us, 10.8%sy,  0.0%ni, 12.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.4%us, 12.2%sy,  0.0%ni, 11.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.3%us, 11.1%sy,  0.0%ni, 10.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 80.2%us,  9.5%sy,  0.0%ni, 10.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 80.0%us,  8.8%sy,  0.0%ni, 11.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 80.7%us,  9.1%sy,  0.0%ni, 10.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.1%us, 11.0%sy,  0.0%ni, 10.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 82.0%us,  7.8%sy,  0.0%ni, 10.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.4%us, 10.3%sy,  0.0%ni, 11.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 79.1%us,  8.3%sy,  0.0%ni, 12.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.5%us, 10.9%sy,  0.0%ni, 11.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.5%us, 11.4%sy,  0.0%ni, 10.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 79.4%us,  9.6%sy,  0.0%ni, 11.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.9%us,  8.6%sy,  0.0%ni, 14.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 61.5%us,  4.5%sy,  0.0%ni, 34.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 46.2%us,  2.5%sy,  0.0%ni, 51.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 12.6%us,  0.7%sy,  0.0%ni, 86.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.2%us,  0.1%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~11%
-----------
# time GC_INITIAL_HEAP_SIZE=104857600 ./program.exe example.log
real	0m51.476s
user	5m5.350s
sys	0m33.844s
# (GC_INITIAL_HEAP_SIZE=104857600 ./program.exe example.log &); top -b
| grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.7%us, 12.5%sy,  0.0%ni, 10.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.6%us, 11.8%sy,  0.0%ni, 11.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 75.7%us, 12.5%sy,  0.0%ni, 11.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.8%us, 11.6%sy,  0.0%ni, 11.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.9%us, 11.7%sy,  0.0%ni, 11.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.6%us, 11.4%sy,  0.0%ni, 11.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.6%us, 11.8%sy,  0.0%ni, 11.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.9%us, 11.0%sy,  0.0%ni, 12.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.0%us, 12.0%sy,  0.0%ni, 12.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 78.0%us, 11.1%sy,  0.0%ni, 10.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 75.3%us, 13.0%sy,  0.0%ni, 11.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 76.9%us, 11.8%sy,  0.0%ni, 11.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.0%us, 10.2%sy,  0.0%ni, 12.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 51.3%us,  5.0%sy,  0.0%ni, 43.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 25.6%us,  0.8%sy,  0.0%ni, 73.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 18.7%us,  0.8%sy,  0.0%ni, 80.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.3%us,  0.1%sy,  0.0%ni, 99.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~11%
-----------
# time ./MultipleReader.exe example.log
real	0m24.655s
user	2m59.065s
sys	0m9.483s
# (./MultipleReader.exe example.log &); top -b | grep 'Cpu(s)'
Cpu(s):  2.2%us,  0.5%sy,  0.4%ni, 96.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 94.2%us,  5.4%sy,  0.0%ni,  0.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 94.7%us,  5.1%sy,  0.0%ni,  0.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 93.4%us,  5.2%sy,  0.0%ni,  1.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 95.3%us,  4.7%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 93.3%us,  5.0%sy,  0.0%ni,  1.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 94.2%us,  5.5%sy,  0.0%ni,  0.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 91.4%us,  5.0%sy,  0.0%ni,  3.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s): 77.5%us,  3.7%sy,  0.0%ni, 18.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu(s):  0.4%us,  0.1%sy,  0.0%ni, 99.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

idle: ~1%
-----------

The multiprocess version is still the best. And it is a pity. The
original program queries a DB, with a multithread version all threads
can share a cache, and only query the DB the first time an ID is
needed. I can't do that with a multiprocess program just as easily.

OTOH and as a curiosity: Is there any way to free memory directly (at
CIL level I mean) without using the GC? for instance:

   while ((Str = SR.ReadLine()) != null) ;

with a little flow analisis we can determine Str isn't used after it
is assigned. is there a way to deallocate it efficiently without
waiting for the GC to collect memory?

Best regards
          Yanko


More information about the Mono-list mailing list