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/201012070034/aptitude-trendy-1.0/randc192b7.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//randc192b7.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randc192b7.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.20 1.10 1.03 2/41 5956
/proc/meminfo: memFree=744764/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 517 1360 0 0 0 0 0 0 25 0 1 0 885451647 2641920 280 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 280 237 194 0 31 0
[pid=5956] ppid=5948 vsize=2004 CPUtime=0
/proc/5956/stat : 5956 (cp) R 5948 5948 4159 34819 4229 4202496 254 0 0 0 0 0 0 0 25 0 1 0 885451648 2052096 183 1283457024 134512640 134614052 4292651136 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/5956/statm: 501 183 145 25 0 47 0

[startup+0.199927 s]
/proc/loadavg: 1.20 1.10 1.03 2/41 5956
/proc/meminfo: memFree=744764/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.209923 s]
/proc/loadavg: 1.20 1.10 1.03 2/41 5956
/proc/meminfo: memFree=744764/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.309972 s]
/proc/loadavg: 1.20 1.10 1.03 2/41 5956
/proc/meminfo: memFree=744764/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.710063 s]
/proc/loadavg: 1.20 1.10 1.03 2/41 5956
/proc/meminfo: memFree=744764/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+1.5102 s]
/proc/loadavg: 1.20 1.10 1.03 2/42 5959
/proc/meminfo: memFree=713688/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
[pid=5959] ppid=5948 vsize=34424 CPUtime=1.48
/proc/5959/stat : 5959 (cudftodeb.nativ) R 5948 5948 4159 34819 4229 4202496 8173 0 0 0 144 4 0 0 25 0 1 0 885451650 35250176 8100 1283457024 134512640 135004320 4294828624 18446744073709551615 134951465 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5959/statm: 8606 8100 225 121 0 7998 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 37004

[startup+3.1105 s]
/proc/loadavg: 1.18 1.10 1.03 2/42 5959
/proc/meminfo: memFree=688516/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2580 CPUtime=0.02
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 566 1861 0 0 0 0 0 2 25 0 1 0 885451647 2641920 283 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 645 283 240 194 0 31 0
[pid=5959] ppid=5948 vsize=31472 CPUtime=3.08
/proc/5959/stat : 5959 (cudftodeb.nativ) R 5948 5948 4159 34819 4229 4202496 12311 0 0 0 301 7 0 0 25 0 1 0 885451650 32227328 7419 1283457024 134512640 135004320 4294828624 18446744073709551615 134867640 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5959/statm: 7868 7419 237 121 0 7260 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 34052

[startup+6.30889 s]
/proc/loadavg: 1.18 1.10 1.03 2/42 5970
/proc/meminfo: memFree=683736/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=3.49
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 691 18011 0 1 0 0 336 13 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
[pid=5969] ppid=5948 vsize=49896 CPUtime=1.58
/proc/5969/stat : 5969 (aptitude) R 5948 5948 4159 34819 4229 4202496 10638 651 177 0 148 10 0 0 20 0 2 0 885452044 51093504 6757 1283457024 134512640 137933492 4288378912 18446744073709551615 4153646380 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5969/statm: 12474 6757 4166 836 0 6690 0
Current children cumulated CPU time (s) 5.07
Current children cumulated vsize (KiB) 52484

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

[startup+6.40892 s]
/proc/loadavg: 1.18 1.10 1.03 2/42 5970
/proc/meminfo: memFree=683736/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=3.49
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 691 18011 0 1 0 0 336 13 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
[pid=5969] ppid=5948 vsize=49896 CPUtime=1.68
/proc/5969/stat : 5969 (aptitude) R 5948 5948 4159 34819 4229 4202496 10639 651 177 0 158 10 0 0 20 0 2 0 885452044 51093504 6757 1283457024 134512640 137933492 4288378912 18446744073709551615 4155297960 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5969/statm: 12474 6757 4166 836 0 6690 0
Current children cumulated CPU time (s) 5.17
Current children cumulated vsize (KiB) 52484

[startup+7.20909 s]
/proc/loadavg: 1.18 1.10 1.03 3/43 5973
/proc/meminfo: memFree=677776/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=5.69
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 718 32410 0 178 0 0 544 25 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
Current children cumulated CPU time (s) 5.69
Current children cumulated vsize (KiB) 2588

[startup+8.00927 s]
/proc/loadavg: 1.17 1.10 1.03 2/42 5975
/proc/meminfo: memFree=672824/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=5.69
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 718 32410 0 178 0 0 544 25 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
[pid=5975] ppid=5948 vsize=26196 CPUtime=1.07
/proc/5975/stat : 5975 (aptsolutions.na) R 5948 5948 4159 34819 4229 4202496 6188 0 0 0 104 3 0 0 24 0 1 0 885452340 26824704 6076 1283457024 134512640 134971616 4293556480 18446744073709551615 134946665 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5975/statm: 6549 6076 204 113 0 5951 0
Current children cumulated CPU time (s) 6.76
Current children cumulated vsize (KiB) 28784

[startup+8.40937 s]
/proc/loadavg: 1.17 1.10 1.03 2/42 5975
/proc/meminfo: memFree=672824/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=5.69
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 718 32410 0 178 0 0 544 25 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
[pid=5975] ppid=5948 vsize=35568 CPUtime=1.47
/proc/5975/stat : 5975 (aptsolutions.na) R 5948 5948 4159 34819 4229 4202496 8469 0 0 0 143 4 0 0 25 0 1 0 885452340 36421632 8355 1283457024 134512640 134971616 4293556480 18446744073709551615 134964252 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5975/statm: 8892 8355 208 113 0 8294 0
Current children cumulated CPU time (s) 7.16
Current children cumulated vsize (KiB) 38156

[startup+8.5094 s]
/proc/loadavg: 1.17 1.10 1.03 2/42 5975
/proc/meminfo: memFree=672824/1048576 swapFree=2077620/2097144
[pid=5948] ppid=5947 vsize=2588 CPUtime=5.69
/proc/5948/stat : 5948 (aptitude-trendy) S 5947 5948 4159 34819 4229 4202496 718 32410 0 178 0 0 544 25 18 0 1 0 885451647 2650112 294 1283457024 134512640 135304128 4288088992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5948/statm: 647 294 249 194 0 33 0
[pid=5975] ppid=5948 vsize=41056 CPUtime=1.57
/proc/5975/stat : 5975 (aptsolutions.na) R 5948 5948 4159 34819 4229 4202496 9801 0 0 0 153 4 0 0 25 0 1 0 885452340 42041344 9687 1283457024 134512640 134971616 4293556480 18446744073709551615 134911423 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5975/statm: 10264 9687 209 113 0 9666 0
Current children cumulated CPU time (s) 7.26
Current children cumulated vsize (KiB) 43644

Child status: 0
Real time (s): 8.57137
CPU time (s): 7.34446
CPU user time (s): 7.03644
CPU system time (s): 0.308019
CPU usage (%): 85.686
Max. virtual memory (cumulated for all children) (KiB): 110996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.03644
system time used= 0.308019
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44299
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= 236
involuntary context switches= 252

runsolver used 0 second user time and 0.012 second system time

The end