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/rand4d6b1c.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//rand4d6b1c.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand4d6b1c.cudf.difficult.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.12 1.18 1.12 2/45 20649
/proc/meminfo: memFree=711656/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=820 CPUtime=0.01
/proc/20649/stat : 20649 (aptitude-parano) R 20648 20649 2059 34821 2220 4194304 74 0 0 0 0 1 0 0 25 0 1 0 875944937 839680 2 1283457024 0 0 4287140652 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/20649/statm: 205 2 0 0 0 6 0

[startup+0.200448 s]
/proc/loadavg: 1.12 1.18 1.12 2/45 20649
/proc/meminfo: memFree=711656/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2584

[startup+0.310474 s]
/proc/loadavg: 1.12 1.18 1.12 2/45 20649
/proc/meminfo: memFree=711656/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2584

[startup+0.4105 s]
/proc/loadavg: 1.12 1.18 1.12 2/45 20649
/proc/meminfo: memFree=711656/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2584

[startup+0.710568 s]
/proc/loadavg: 1.12 1.18 1.12 2/45 20649
/proc/meminfo: memFree=711656/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2584

[startup+1.51076 s]
/proc/loadavg: 1.12 1.18 1.12 2/47 20660
/proc/meminfo: memFree=673464/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
[pid=20660] ppid=20649 vsize=34000 CPUtime=1.47
/proc/20660/stat : 20660 (cudftodeb.nativ) R 20649 20649 2059 34821 2220 4202496 8031 0 0 0 144 3 0 0 25 0 1 0 875944941 34816000 7958 1283457024 134512640 135004320 4292882544 18446744073709551615 4158826049 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/20660/statm: 8500 7958 225 121 0 7892 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36584

[startup+3.11122 s]
/proc/loadavg: 1.12 1.18 1.12 2/47 20660
/proc/meminfo: memFree=651144/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2584 CPUtime=0.03
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 566 1858 0 0 0 1 0 2 25 0 1 0 875944937 2646016 283 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 646 283 240 194 0 32 0
[pid=20660] ppid=20649 vsize=68856 CPUtime=3.08
/proc/20660/stat : 20660 (cudftodeb.nativ) R 20649 20649 2059 34821 2220 4202496 16648 0 0 0 300 8 0 0 25 0 1 0 875944941 70508544 16575 1283457024 134512640 135004320 4292882544 18446744073709551615 134525963 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/20660/statm: 17214 16575 237 121 0 16606 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 71440

[startup+6.3048 s]
/proc/loadavg: 1.11 1.17 1.12 2/49 20668
/proc/meminfo: memFree=664132/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=5.55
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 650 25894 0 0 0 1 532 22 18 0 1 0 875944937 2654208 286 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 286 241 194 0 34 0
[pid=20664] ppid=20649 vsize=101500 CPUtime=0.21
/proc/20664/stat : 20664 (apt-get) D 20649 20649 2059 34821 2220 4202496 548 1681 1 0 0 0 19 2 24 0 1 0 875945492 103936000 421 1283457024 134512640 134619611 4289868720 18446744073709551615 4294960130 0 0 4096 134217728 18446744071696460772 0 0 17 0 0 0 0
/proc/20664/statm: 25375 421 374 27 0 69 0
Current children cumulated CPU time (s) 5.76
Current children cumulated vsize (KiB) 104092

[startup+12.7086 s]
/proc/loadavg: 1.10 1.17 1.12 2/48 20674
/proc/meminfo: memFree=603908/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=5.79
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 696 28297 0 1 0 1 554 24 18 0 1 0 875944937 2654208 294 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 294 249 194 0 34 0
[pid=20670] ppid=20649 vsize=66240 CPUtime=5.09
/proc/20670/stat : 20670 (aptitude) R 20649 20649 2059 34821 2220 4202496 19580 1062 266 0 499 10 0 0 25 0 2 0 875945580 67829760 10888 1283457024 134512640 137933492 4292813728 18446744073709551615 4159415783 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/20670/statm: 16560 10888 5751 836 0 9192 0
[pid=20670/tid=20672] ppid=20649 vsize=66240 CPUtime=1.21
/proc/20670/task/20672/stat : 20672 (aptitude) S 20649 20649 2059 34821 2220 4202560 3080 1062 0 0 120 1 0 0 17 0 2 0 875945826 67829760 10888 1283457024 134512640 137933492 4292813728 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680193024 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.88
Current children cumulated vsize (KiB) 68832

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

[startup+12.9086 s]
/proc/loadavg: 1.10 1.17 1.12 2/48 20674
/proc/meminfo: memFree=603908/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=5.79
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 696 28297 0 1 0 1 554 24 18 0 1 0 875944937 2654208 294 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 294 249 194 0 34 0
[pid=20670] ppid=20649 vsize=66240 CPUtime=5.29
/proc/20670/stat : 20670 (aptitude) R 20649 20649 2059 34821 2220 4202496 19580 1062 266 0 519 10 0 0 25 0 2 0 875945580 67829760 10888 1283457024 134512640 137933492 4292813728 18446744073709551615 4159493675 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/20670/statm: 16560 10888 5751 836 0 9192 0
[pid=20670/tid=20672] ppid=20649 vsize=66240 CPUtime=1.21
/proc/20670/task/20672/stat : 20672 (aptitude) S 20649 20649 2059 34821 2220 4202560 3080 1062 0 0 120 1 0 0 17 0 2 0 875945826 67829760 10888 1283457024 134512640 137933492 4292813728 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680193024 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.08
Current children cumulated vsize (KiB) 68832

[startup+14.5089 s]
/proc/loadavg: 1.17 1.18 1.12 2/47 20676
/proc/meminfo: memFree=597220/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=11.24
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 723 49039 0 267 0 1 1088 35 18 0 1 0 875944937 2654208 294 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 294 249 194 0 34 0
[pid=20676] ppid=20649 vsize=33212 CPUtime=1.43
/proc/20676/stat : 20676 (aptsolutions.na) R 20649 20649 2059 34821 2220 4202496 7887 0 0 0 139 4 0 0 25 0 1 0 875946244 34009088 7774 1283457024 134512640 134971616 4286956208 18446744073709551615 4158338639 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/20676/statm: 8303 7774 204 113 0 7705 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 35804

[startup+15.309 s]
/proc/loadavg: 1.17 1.18 1.12 2/47 20676
/proc/meminfo: memFree=597220/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=11.24
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 723 49039 0 267 0 1 1088 35 18 0 1 0 875944937 2654208 294 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 294 249 194 0 34 0
[pid=20676] ppid=20649 vsize=49956 CPUtime=2.23
/proc/20676/stat : 20676 (aptsolutions.na) R 20649 20649 2059 34821 2220 4202496 12004 0 0 0 217 6 0 0 25 0 1 0 875946244 51154944 11891 1283457024 134512640 134971616 4286956208 18446744073709551615 4158338639 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/20676/statm: 12489 11891 204 113 0 11891 0
Current children cumulated CPU time (s) 13.47
Current children cumulated vsize (KiB) 52548

[startup+15.509 s]
/proc/loadavg: 1.17 1.18 1.12 2/47 20676
/proc/meminfo: memFree=573040/1048576 swapFree=2078744/2097144
[pid=20649] ppid=20648 vsize=2592 CPUtime=11.24
/proc/20649/stat : 20649 (aptitude-parano) S 20648 20649 2059 34821 2220 4202496 723 49039 0 267 0 1 1088 35 18 0 1 0 875944937 2654208 294 1283457024 134512640 135304128 4287134368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/20649/statm: 648 294 249 194 0 34 0
[pid=20676] ppid=20649 vsize=56312 CPUtime=2.43
/proc/20676/stat : 20676 (aptsolutions.na) R 20649 20649 2059 34821 2220 4202496 13593 0 0 0 237 6 0 0 25 0 1 0 875946244 57663488 13480 1283457024 134512640 134971616 4286956208 18446744073709551615 134847229 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/20676/statm: 14078 13480 209 113 0 13480 0
Current children cumulated CPU time (s) 13.67
Current children cumulated vsize (KiB) 58904

Child status: 0
Real time (s): 15.545
CPU time (s): 13.7289
CPU user time (s): 13.2848
CPU system time (s): 0.444027
CPU usage (%): 88.317
Max. virtual memory (cumulated for all children) (KiB): 111004

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

runsolver used 0 second user time and 0 second system time

The end