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/randf17677.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//randf17677.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randf17677.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: 0.99 1.00 0.99 2/41 6703
/proc/meminfo: memFree=749020/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=3764 CPUtime=0.05
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 643 0 0 0 5 0 0 0 25 0 1 0 885600519 3854336 570 1283457024 134512640 135004320 4294042000 18446744073709551615 134986355 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 941 570 224 121 0 333 0

[startup+0.245861 s]
/proc/loadavg: 0.99 1.00 0.99 2/41 6703
/proc/meminfo: memFree=749020/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=7484 CPUtime=0.22
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 1541 0 0 0 22 0 0 0 25 0 1 0 885600519 7663616 1468 1283457024 134512640 135004320 4294042000 18446744073709551615 134986387 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 1871 1468 225 121 0 1263 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 10064

[startup+0.305878 s]
/proc/loadavg: 0.99 1.00 0.99 2/41 6703
/proc/meminfo: memFree=749020/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=8724 CPUtime=0.28
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 1845 0 0 0 28 0 0 0 25 0 1 0 885600519 8933376 1772 1283457024 134512640 135004320 4294042000 18446744073709551615 134986403 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 2181 1772 225 121 0 1573 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 11304

[startup+0.405907 s]
/proc/loadavg: 0.99 1.00 0.99 2/41 6703
/proc/meminfo: memFree=749020/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=10708 CPUtime=0.38
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 2375 0 0 0 38 0 0 0 25 0 1 0 885600519 10964992 2302 1283457024 134512640 135004320 4294042000 18446744073709551615 134951585 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 2677 2302 225 121 0 2069 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 13288

[startup+0.705987 s]
/proc/loadavg: 0.99 1.00 0.99 2/41 6703
/proc/meminfo: memFree=749020/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=17564 CPUtime=0.67
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 4010 0 0 0 67 0 0 0 25 0 1 0 885600519 17985536 3937 1283457024 134512640 135004320 4294042000 18446744073709551615 134808339 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 4391 3937 225 121 0 3783 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 20144

[startup+1.50623 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6704
/proc/meminfo: memFree=725080/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=33752 CPUtime=1.47
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 8017 0 0 0 146 1 0 0 25 0 1 0 885600519 34562048 7944 1283457024 134512640 135004320 4294042000 18446744073709551615 134945054 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 8438 7944 225 121 0 7830 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 36332

[startup+3.10674 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6704
/proc/meminfo: memFree=702760/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2580 CPUtime=0.02
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 556 1861 0 0 0 0 0 2 25 0 1 0 885600516 2641920 282 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 645 282 240 194 0 31 0
[pid=6703] ppid=6693 vsize=68856 CPUtime=3.07
/proc/6703/stat : 6703 (cudftodeb.nativ) R 6693 6693 4159 34819 4229 4202496 16627 0 0 0 300 7 0 0 25 0 1 0 885600519 70508544 16554 1283457024 134512640 135004320 4294042000 18446744073709551615 4158505632 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6703/statm: 17214 16554 237 121 0 16606 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 71436

[startup+6.30412 s]
/proc/loadavg: 0.99 1.00 0.99 3/44 6712
/proc/meminfo: memFree=715624/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=5.53
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 636 25899 0 0 0 0 536 17 21 0 1 0 885600516 2650112 285 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 285 241 194 0 33 0
[pid=6708] ppid=6693 vsize=101504 CPUtime=0.21
/proc/6708/stat : 6708 (apt-get) D 6693 6693 4159 34819 4229 4202496 549 1681 1 0 0 0 18 3 24 0 1 0 885601070 103940096 422 1283457024 134512640 134619611 4294305808 18446744073709551615 4294960130 0 0 4096 134217728 18446744071696460772 0 0 17 0 0 0 0
/proc/6708/statm: 25376 422 374 27 0 70 0
Current children cumulated CPU time (s) 5.74
Current children cumulated vsize (KiB) 104092

[startup+12.7095 s]
/proc/loadavg: 0.99 1.00 0.99 2/43 6717
/proc/meminfo: memFree=666012/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=5.77
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 679 28299 0 1 0 0 557 20 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6714] ppid=6693 vsize=58272 CPUtime=4.96
/proc/6714/stat : 6714 (aptitude) R 6693 6693 4159 34819 4229 4202496 14360 241 267 0 419 77 0 0 25 0 2 0 885601191 59670528 9004 1283457024 134512640 137933492 4287868624 18446744073709551615 134639297 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6714/statm: 14568 9004 5878 836 0 7200 0
[pid=6714/tid=6716] ppid=6693 vsize=58272 CPUtime=0
/proc/6714/task/6716/stat : 6716 (aptitude) S 6693 6693 4159 34819 4229 4202560 3 241 0 0 0 0 0 0 17 0 2 0 885601428 59670528 9004 1283457024 134512640 137933492 4287868624 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393160064 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.73
Current children cumulated vsize (KiB) 60860

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

[startup+12.9096 s]
/proc/loadavg: 0.99 1.00 0.99 2/43 6717
/proc/meminfo: memFree=666012/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=5.77
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 679 28299 0 1 0 0 557 20 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6714] ppid=6693 vsize=58272 CPUtime=5.16
/proc/6714/stat : 6714 (aptitude) R 6693 6693 4159 34819 4229 4202496 14363 241 267 0 439 77 0 0 25 0 2 0 885601191 59670528 9007 1283457024 134512640 137933492 4287868624 18446744073709551615 4155103534 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6714/statm: 14568 9007 5878 836 0 7200 0
[pid=6714/tid=6716] ppid=6693 vsize=58272 CPUtime=0
/proc/6714/task/6716/stat : 6716 (aptitude) S 6693 6693 4159 34819 4229 4202560 3 241 0 0 0 0 0 0 17 0 2 0 885601428 59670528 9007 1283457024 134512640 137933492 4287868624 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393160064 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.93
Current children cumulated vsize (KiB) 60860

[startup+14.5102 s]
/proc/loadavg: 0.99 1.00 0.99 2/43 6719
/proc/meminfo: memFree=658936/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=5.77
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 679 28299 0 1 0 0 557 20 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6714] ppid=6693 vsize=64364 CPUtime=6.77
/proc/6714/stat : 6714 (aptitude) R 6693 6693 4159 34819 4229 4202496 18819 1060 267 0 596 81 0 0 25 0 2 0 885601191 65908736 10648 1283457024 134512640 137933492 4287868624 18446744073709551615 4159812680 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6714/statm: 16091 10648 6008 836 0 8723 0
[pid=6714/tid=6716] ppid=6693 vsize=64364 CPUtime=0.47
/proc/6714/task/6716/stat : 6716 (aptitude) S 6693 6693 4159 34819 4229 4202560 2122 1060 0 0 46 1 0 0 16 0 2 0 885601428 65908736 10648 1283457024 134512640 137933492 4287868624 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393160064 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 66952

[startup+16.111 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6720
/proc/meminfo: memFree=667508/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=13.08
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 705 48319 0 268 0 0 1205 103 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6720] ppid=6693 vsize=25776 CPUtime=1.04
/proc/6720/stat : 6720 (aptsolutions.na) R 6693 6693 4159 34819 4229 4202496 6028 0 0 0 101 3 0 0 25 0 1 0 885602021 26394624 5916 1283457024 134512640 134971616 4291692336 18446744073709551615 134915825 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6720/statm: 6444 5916 204 113 0 5846 0
Current children cumulated CPU time (s) 14.12
Current children cumulated vsize (KiB) 28364

[startup+16.9112 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6720
/proc/meminfo: memFree=644444/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=13.08
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 705 48319 0 268 0 0 1205 103 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6720] ppid=6693 vsize=43016 CPUtime=1.83
/proc/6720/stat : 6720 (aptsolutions.na) R 6693 6693 4159 34819 4229 4202496 10297 0 0 0 178 5 0 0 25 0 1 0 885602021 44048384 10185 1283457024 134512640 134971616 4291692336 18446744073709551615 134953906 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6720/statm: 10754 10185 204 113 0 10156 0
Current children cumulated CPU time (s) 14.91
Current children cumulated vsize (KiB) 45604

[startup+17.3113 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6720
/proc/meminfo: memFree=644444/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=13.08
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 705 48319 0 268 0 0 1205 103 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6720] ppid=6693 vsize=50952 CPUtime=2.24
/proc/6720/stat : 6720 (aptsolutions.na) R 6693 6693 4159 34819 4229 4202496 12220 0 0 0 216 8 0 0 25 0 1 0 885602021 52174848 12108 1283457024 134512640 134971616 4291692336 18446744073709551615 134963735 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6720/statm: 12738 12108 204 113 0 12140 0
Current children cumulated CPU time (s) 15.32
Current children cumulated vsize (KiB) 53540

[startup+17.4114 s]
/proc/loadavg: 0.99 1.00 0.99 2/42 6720
/proc/meminfo: memFree=644444/1048576 swapFree=2077680/2097144
[pid=6693] ppid=6692 vsize=2588 CPUtime=13.08
/proc/6693/stat : 6693 (aptitude-trendy) S 6692 6693 4159 34819 4229 4202496 705 48319 0 268 0 0 1205 103 18 0 1 0 885600516 2650112 293 1283457024 134512640 135304128 4290678288 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6693/statm: 647 293 249 194 0 33 0
[pid=6720] ppid=6693 vsize=54056 CPUtime=2.34
/proc/6720/stat : 6720 (aptsolutions.na) R 6693 6693 4159 34819 4229 4202496 12996 0 0 0 226 8 0 0 25 0 1 0 885602021 55353344 12884 1283457024 134512640 134971616 4291692336 18446744073709551615 4159080017 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6720/statm: 13514 12884 208 113 0 12916 0
Current children cumulated CPU time (s) 15.42
Current children cumulated vsize (KiB) 56644

Child status: 0
Real time (s): 17.5001
CPU time (s): 15.513
CPU user time (s): 14.3849
CPU system time (s): 1.12807
CPU usage (%): 88.6448
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.3849
system time used= 1.12807
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63203
page faults= 268
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 292
involuntary context switches= 374

runsolver used 0 second user time and 0 second system time

The end