runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand494.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand494.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand494.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.84 0.94 0.90 3/39 11003
/proc/meminfo: memFree=91568/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=1916 CPUtime=0
/proc/11003/stat : 11003 (cudf_msu32) D 11002 11002 9023 34817 9081 4202496 264 0 0 0 0 0 0 0 18 0 1 0 893330212 1961984 157 1283457024 134512640 136125367 4294709792 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/11003/statm: 479 157 133 394 0 83 0

[startup+0.164389 s]
/proc/loadavg: 0.84 0.94 0.90 3/39 11003
/proc/meminfo: memFree=91568/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=7924 CPUtime=0.13
/proc/11003/stat : 11003 (cudf_msu32) R 11002 11002 9023 34817 9081 4202496 1790 0 0 0 13 0 0 0 25 0 1 0 893330212 8114176 1683 1283457024 134512640 136125367 4294709792 18446744073709551615 134717834 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11003/statm: 1981 1683 143 394 0 1585 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10492

[startup+0.204388 s]
/proc/loadavg: 0.84 0.94 0.90 3/39 11003
/proc/meminfo: memFree=91568/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=9508 CPUtime=0.16
/proc/11003/stat : 11003 (cudf_msu32) R 11002 11002 9023 34817 9081 4202496 2196 0 0 0 16 0 0 0 25 0 1 0 893330212 9736192 2089 1283457024 134512640 136125367 4294709792 18446744073709551615 135528911 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11003/statm: 2377 2089 143 394 0 1981 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12076

[startup+0.306676 s]
/proc/loadavg: 0.84 0.94 0.90 3/39 11003
/proc/meminfo: memFree=91568/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=13088 CPUtime=0.26
/proc/11003/stat : 11003 (cudf_msu32) R 11002 11002 9023 34817 9081 4202496 3074 0 0 0 26 0 0 0 25 0 1 0 893330212 13402112 2967 1283457024 134512640 136125367 4294709792 18446744073709551615 134717885 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11003/statm: 3272 2967 144 394 0 2876 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 15656

[startup+0.704424 s]
/proc/loadavg: 0.84 0.94 0.90 3/39 11003
/proc/meminfo: memFree=91568/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=25032 CPUtime=0.6
/proc/11003/stat : 11003 (cudf_msu32) R 11002 11002 9023 34817 9081 4202496 6083 0 0 0 57 3 0 0 25 0 1 0 893330212 25632768 5976 1283457024 134512640 136125367 4294709792 18446744073709551615 134717968 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11003/statm: 6258 5976 144 394 0 5862 0
Current children cumulated CPU time (s) 0.6
Current children cumulated vsize (KiB) 27600

[startup+1.51203 s]
/proc/loadavg: 0.84 0.94 0.90 2/40 11004
/proc/meminfo: memFree=40144/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=0
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893330212 2629632 278 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 278 238 194 0 28 0
[pid=11003] ppid=11002 vsize=47356 CPUtime=1.35
/proc/11003/stat : 11003 (cudf_msu32) R 11002 11002 9023 34817 9081 4202496 11736 0 0 0 116 19 0 0 25 0 1 0 893330212 48492544 11580 1283457024 134512640 136125367 4294709792 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11003/statm: 11839 11580 165 394 0 11443 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 49924

[startup+3.11243 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 11005
/proc/meminfo: memFree=56396/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=1.66
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 401 11738 0 0 0 0 129 37 20 0 1 0 893330212 2629632 281 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 281 241 194 0 28 0
[pid=11005] ppid=11002 vsize=16436 CPUtime=1.27
/proc/11005/stat : 11005 (bmo-pblex32) R 11002 11002 9023 34817 9081 4202496 4418 0 0 0 100 27 0 0 25 0 1 0 893330394 16830464 3795 1283457024 134512640 135887319 4287597408 18446744073709551615 134624768 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11005/statm: 4109 3795 138 336 0 3771 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 19004

Solver just ended. Dumping a history of the last processes samples

[startup+3.20245 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 11005
/proc/meminfo: memFree=56396/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=1.66
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 401 11738 0 0 0 0 129 37 20 0 1 0 893330212 2629632 281 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 281 241 194 0 28 0
[pid=11005] ppid=11002 vsize=16436 CPUtime=1.36
/proc/11005/stat : 11005 (bmo-pblex32) R 11002 11002 9023 34817 9081 4202496 4425 0 0 0 108 28 0 0 25 0 1 0 893330394 16830464 3802 1283457024 134512640 135887319 4287597408 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11005/statm: 4109 3802 138 336 0 3771 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 19004

[startup+4.00902 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 11005
/proc/meminfo: memFree=51560/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=1.66
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 401 11738 0 0 0 0 129 37 20 0 1 0 893330212 2629632 281 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 281 241 194 0 28 0
[pid=11005] ppid=11002 vsize=22284 CPUtime=2.08
/proc/11005/stat : 11005 (bmo-pblex32) R 11002 11002 9023 34817 9081 4202496 6586 0 0 0 164 44 0 0 25 0 1 0 893330394 22818816 5262 1283457024 134512640 135887319 4287597408 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11005/statm: 5571 5262 144 336 0 5233 0
Current children cumulated CPU time (s) 3.74
Current children cumulated vsize (KiB) 24852

[startup+4.80915 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 11005
/proc/meminfo: memFree=49576/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=1.66
/proc/11002/stat : 11002 (cudf2pbo4parano) S 11001 11002 9023 34817 9081 4202496 401 11738 0 0 0 0 129 37 20 0 1 0 893330212 2629632 281 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11002/statm: 642 281 241 194 0 28 0
[pid=11005] ppid=11002 vsize=23520 CPUtime=2.86
/proc/11005/stat : 11005 (bmo-pblex32) R 11002 11002 9023 34817 9081 4202496 6912 0 0 0 230 56 0 0 25 0 1 0 893330394 24084480 5583 1283457024 134512640 135887319 4287597408 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11005/statm: 5880 5583 144 336 0 5542 0
Current children cumulated CPU time (s) 4.52
Current children cumulated vsize (KiB) 26088

[startup+5.00918 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 11005
/proc/meminfo: memFree=49576/1048576 swapFree=2095372/2097144
[pid=11002] ppid=11001 vsize=2568 CPUtime=4.69
/proc/11002/stat : 11002 (cudf2pbo4parano) R 11001 11002 9023 34817 9081 4202496 420 18723 0 0 0 0 374 95 18 0 1 0 893330212 2629632 281 1283457024 134512640 135304128 4286908960 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11002/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 4.69
Current children cumulated vsize (KiB) 2568

Child status: 0
Real time (s): 5.03329
CPU time (s): 4.7603
CPU user time (s): 3.79624
CPU system time (s): 0.96406
CPU usage (%): 94.5763
Max. virtual memory (cumulated for all children) (KiB): 49924

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.79624
system time used= 0.96406
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 21013
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 55
involuntary context switches= 2029

runsolver used 0 second user time and 0.008 second system time

The end