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/rand49d73b.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//rand49d73b.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand49d73b.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.19 1.10 1.05 2/46 21415
/proc/meminfo: memFree=824012/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=3028 CPUtime=0
/proc/21415/stat : 21415 (runsolver) D 21414 21415 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 881772821 3100672 94 1283457024 134512640 134586868 4293457888 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/21415/statm: 757 94 62 19 0 55 0

[startup+0.1636 s]
/proc/loadavg: 1.19 1.10 1.05 2/46 21415
/proc/meminfo: memFree=824012/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.21362 s]
/proc/loadavg: 1.19 1.10 1.05 2/46 21415
/proc/meminfo: memFree=824012/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.313643 s]
/proc/loadavg: 1.19 1.10 1.05 2/46 21415
/proc/meminfo: memFree=824012/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.713732 s]
/proc/loadavg: 1.19 1.10 1.05 2/46 21415
/proc/meminfo: memFree=824012/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.51396 s]
/proc/loadavg: 1.19 1.10 1.05 2/48 21426
/proc/meminfo: memFree=788076/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
[pid=21426] ppid=21415 vsize=32760 CPUtime=1.44
/proc/21426/stat : 21426 (cudftodeb.nativ) R 21415 21415 4159 34819 4229 4202496 7769 0 8 0 142 2 0 0 25 0 1 0 881772826 33546240 7704 1283457024 134512640 135004320 4292524864 18446744073709551615 134986315 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21426/statm: 8190 7704 225 121 0 7582 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 35344

[startup+3.11437 s]
/proc/loadavg: 1.19 1.10 1.05 2/48 21426
/proc/meminfo: memFree=766128/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2584 CPUtime=0.02
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 557 1858 0 0 0 0 0 2 25 0 1 0 881772821 2646016 283 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 646 283 240 194 0 32 0
[pid=21426] ppid=21415 vsize=67116 CPUtime=3.03
/proc/21426/stat : 21426 (cudftodeb.nativ) R 21415 21415 4159 34819 4229 4202496 16180 0 8 0 295 8 0 0 25 0 1 0 881772826 68726784 16115 1283457024 134512640 135004320 4292524864 18446744073709551615 4159223903 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21426/statm: 16779 16115 237 121 0 16171 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 69700

[startup+6.30488 s]
/proc/loadavg: 1.17 1.10 1.05 2/48 21426
/proc/meminfo: memFree=706980/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=5.66
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 637 25888 0 8 0 0 542 24 18 0 1 0 881772821 2654208 286 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 286 241 194 0 34 0
Current children cumulated CPU time (s) 5.66
Current children cumulated vsize (KiB) 2592

[startup+12.7052 s]
/proc/loadavg: 1.16 1.10 1.05 2/49 21441
/proc/meminfo: memFree=709636/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=10.44
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 706 47874 0 358 0 0 1001 43 18 0 1 0 881772821 2654208 294 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 294 249 194 0 34 0
Current children cumulated CPU time (s) 10.44
Current children cumulated vsize (KiB) 2592

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

[startup+12.8133 s]
/proc/loadavg: 1.16 1.10 1.05 2/49 21441
/proc/meminfo: memFree=709636/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=10.44
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 706 47874 0 358 0 0 1001 43 18 0 1 0 881772821 2654208 294 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 294 249 194 0 34 0
Current children cumulated CPU time (s) 10.44
Current children cumulated vsize (KiB) 2592

[startup+14.4136 s]
/proc/loadavg: 1.15 1.10 1.05 2/48 21442
/proc/meminfo: memFree=691936/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=10.44
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 706 47874 0 358 0 0 1001 43 18 0 1 0 881772821 2654208 294 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 294 249 194 0 34 0
[pid=21442] ppid=21415 vsize=40780 CPUtime=1.74
/proc/21442/stat : 21442 (aptsolutions.na) R 21415 21415 4159 34819 4229 4202496 9735 0 9 0 170 4 0 0 25 0 1 0 881774083 41758720 9632 1283457024 134512640 134971616 4287338816 18446744073709551615 134927606 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21442/statm: 10195 9632 204 113 0 9597 0
Current children cumulated CPU time (s) 12.18
Current children cumulated vsize (KiB) 43372

[startup+14.8136 s]
/proc/loadavg: 1.15 1.10 1.05 2/48 21442
/proc/meminfo: memFree=691936/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=10.44
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 706 47874 0 358 0 0 1001 43 18 0 1 0 881772821 2654208 294 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 294 249 194 0 34 0
[pid=21442] ppid=21415 vsize=48716 CPUtime=2.15
/proc/21442/stat : 21442 (aptsolutions.na) R 21415 21415 4159 34819 4229 4202496 11680 0 9 0 210 5 0 0 25 0 1 0 881774083 49885184 11577 1283457024 134512640 134971616 4287338816 18446744073709551615 134628533 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21442/statm: 12179 11577 204 113 0 11581 0
Current children cumulated CPU time (s) 12.59
Current children cumulated vsize (KiB) 51308

[startup+15.0137 s]
/proc/loadavg: 1.15 1.10 1.05 2/48 21442
/proc/meminfo: memFree=691936/1048576 swapFree=2074020/2097144
[pid=21415] ppid=21414 vsize=2592 CPUtime=10.44
/proc/21415/stat : 21415 (aptitude-trendy) S 21414 21415 4159 34819 4229 4202496 706 47874 0 358 0 0 1001 43 18 0 1 0 881772821 2654208 294 1283457024 134512640 135304128 4291809056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/21415/statm: 648 294 249 194 0 34 0
[pid=21442] ppid=21415 vsize=54052 CPUtime=2.35
/proc/21442/stat : 21442 (aptsolutions.na) R 21415 21415 4159 34819 4229 4202496 12988 0 9 0 230 5 0 0 25 0 1 0 881774083 55349248 12885 1283457024 134512640 134971616 4287338816 18446744073709551615 134942929 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/21442/statm: 13513 12885 208 113 0 12915 0
Current children cumulated CPU time (s) 12.79
Current children cumulated vsize (KiB) 56644

Child status: 0
Real time (s): 15.1129
CPU time (s): 12.8968
CPU user time (s): 12.4048
CPU system time (s): 0.49203
CPU usage (%): 85.3363
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.4048
system time used= 0.49203
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 62885
page faults= 367
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 475
involuntary context switches= 400

runsolver used 0 second user time and 0.004 second system time

The end