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/201012061533/aptitude-paranoid-1.0/rand8d117b.cudf.easy.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/easy//rand8d117b.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand8d117b.cudf.easy.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: 1.28 1.23 1.19 3/46 27982
/proc/meminfo: memFree=781532/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2568 CPUtime=0
/proc/27981/stat : 27981 (aptitude-parano) R 27980 27981 2059 34821 2220 4202496 357 0 0 0 0 0 0 0 25 0 1 0 876375683 2629632 271 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/27981/statm: 642 271 232 194 0 28 0
[pid=27982] ppid=27981 vsize=2568 CPUtime=0
/proc/27982/stat : 27982 (aptitude-parano) R 27981 27981 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 876375683 2629632 39 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/27982/statm: 642 39 0 194 0 28 0

[startup+0.198231 s]
/proc/loadavg: 1.28 1.23 1.19 3/46 27982
/proc/meminfo: memFree=781532/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.208229 s]
/proc/loadavg: 1.28 1.23 1.19 3/46 27982
/proc/meminfo: memFree=781532/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.308246 s]
/proc/loadavg: 1.28 1.23 1.19 3/46 27982
/proc/meminfo: memFree=781532/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.708303 s]
/proc/loadavg: 1.28 1.23 1.19 3/46 27982
/proc/meminfo: memFree=781532/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+1.50842 s]
/proc/loadavg: 1.26 1.22 1.19 2/47 27992
/proc/meminfo: memFree=750016/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
[pid=27992] ppid=27981 vsize=35416 CPUtime=1.48
/proc/27992/stat : 27992 (cudftodeb.nativ) R 27981 27981 2059 34821 2220 4202496 8414 0 0 0 146 2 0 0 25 0 1 0 876375686 36265984 8341 1283457024 134512640 135004320 4291004064 18446744073709551615 134951465 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27992/statm: 8854 8341 225 121 0 8246 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 37996

[startup+3.10866 s]
/proc/loadavg: 1.26 1.22 1.19 2/47 27992
/proc/meminfo: memFree=723976/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2580 CPUtime=0.03
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 876375683 2641920 282 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 645 282 240 194 0 31 0
[pid=27992] ppid=27981 vsize=31476 CPUtime=3.07
/proc/27992/stat : 27992 (cudftodeb.nativ) R 27981 27981 2059 34821 2220 4202496 12312 0 0 0 304 3 0 0 25 0 1 0 876375686 32231424 7420 1283457024 134512640 135004320 4291004064 18446744073709551615 134863609 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27992/statm: 7869 7420 237 121 0 7261 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 34056

[startup+6.30527 s]
/proc/loadavg: 1.26 1.22 1.19 2/48 28005
/proc/meminfo: memFree=716832/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2588 CPUtime=3.42
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 680 18007 0 1 0 0 332 10 18 0 1 0 876375683 2650112 293 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 647 293 249 194 0 33 0
[pid=28002] ppid=27981 vsize=51228 CPUtime=1.77
/proc/28002/stat : 28002 (aptitude) R 27981 27981 2059 34821 2220 4202496 11233 651 177 0 174 2 0 1 20 0 2 0 876376071 52457472 7184 1283457024 134512640 137933492 4289079440 18446744073709551615 136277323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/28002/statm: 12807 7184 4264 836 0 7016 0
[pid=28002/tid=28004] ppid=27981 vsize=51228 CPUtime=0.1
/proc/28002/task/28004/stat : 28004 (aptitude) S 27981 27981 2059 34821 2220 4202560 532 651 0 0 9 0 0 1 16 0 2 0 876376220 52457472 7184 1283457024 134512640 137933492 4289079440 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 53816

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

[startup+6.40531 s]
/proc/loadavg: 1.26 1.22 1.19 2/48 28005
/proc/meminfo: memFree=716832/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2588 CPUtime=3.42
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 680 18007 0 1 0 0 332 10 18 0 1 0 876375683 2650112 293 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 647 293 249 194 0 33 0
[pid=28002] ppid=27981 vsize=51228 CPUtime=1.88
/proc/28002/stat : 28002 (aptitude) R 27981 27981 2059 34821 2220 4202496 12664 1061 177 0 183 4 0 1 22 0 2 0 876376071 52457472 7189 1283457024 134512640 137933492 4289079440 18446744073709551615 4159836459 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/28002/statm: 12807 7189 4269 836 0 7016 0
[pid=28002/tid=28004] ppid=27981 vsize=51228 CPUtime=0.1
/proc/28002/task/28004/stat : 28004 (aptitude) S 27981 27981 2059 34821 2220 4202560 532 1061 0 0 9 0 0 1 16 0 2 0 876376220 52457472 7189 1283457024 134512640 137933492 4289079440 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.3
Current children cumulated vsize (KiB) 53816

[startup+7.20551 s]
/proc/loadavg: 1.24 1.22 1.19 3/47 28008
/proc/meminfo: memFree=726132/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2588 CPUtime=5.47
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 706 31866 0 178 0 0 530 17 18 0 1 0 876375683 2650112 293 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 647 293 249 194 0 33 0
[pid=28008] ppid=27981 vsize=16776 CPUtime=0.62
/proc/28008/stat : 28008 (aptsolutions.na) R 27981 27981 2059 34821 2220 4202496 3811 0 0 0 62 0 0 0 22 0 1 0 876376341 17178624 3698 1283457024 134512640 134971616 4289785184 18446744073709551615 134919329 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/28008/statm: 4194 3698 204 113 0 3596 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 19364

[startup+8.00575 s]
/proc/loadavg: 1.24 1.22 1.19 2/47 28008
/proc/meminfo: memFree=702704/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2588 CPUtime=5.47
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 706 31866 0 178 0 0 530 17 18 0 1 0 876375683 2650112 293 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 647 293 249 194 0 33 0
[pid=28008] ppid=27981 vsize=33392 CPUtime=1.42
/proc/28008/stat : 28008 (aptsolutions.na) R 27981 27981 2059 34821 2220 4202496 7927 0 0 0 139 3 0 0 25 0 1 0 876376341 34193408 7814 1283457024 134512640 134971616 4289785184 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/28008/statm: 8348 7814 204 113 0 7750 0
Current children cumulated CPU time (s) 6.89
Current children cumulated vsize (KiB) 35980

[startup+8.20584 s]
/proc/loadavg: 1.24 1.22 1.19 2/47 28008
/proc/meminfo: memFree=702704/1048576 swapFree=2078764/2097144
[pid=27981] ppid=27980 vsize=2588 CPUtime=5.47
/proc/27981/stat : 27981 (aptitude-parano) S 27980 27981 2059 34821 2220 4202496 706 31866 0 178 0 0 530 17 18 0 1 0 876375683 2650112 293 1283457024 134512640 135304128 4289592576 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27981/statm: 647 293 249 194 0 33 0
[pid=28008] ppid=27981 vsize=44372 CPUtime=1.62
/proc/28008/stat : 28008 (aptsolutions.na) R 27981 27981 2059 34821 2220 4202496 10598 0 0 0 158 4 0 0 25 0 1 0 876376341 45436928 10483 1283457024 134512640 134971616 4289785184 18446744073709551615 134927982 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/28008/statm: 11093 10483 209 113 0 10495 0
Current children cumulated CPU time (s) 7.09
Current children cumulated vsize (KiB) 46960

Child status: 0
Real time (s): 8.24377
CPU time (s): 7.14445
CPU user time (s): 6.91643
CPU system time (s): 0.228014
CPU usage (%): 86.6648
Max. virtual memory (cumulated for all children) (KiB): 110996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.91643
system time used= 0.228014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43991
page faults= 178
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 257
involuntary context switches= 267

runsolver used 0 second user time and 0 second system time

The end