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/rand6d933e.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//rand6d933e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand6d933e.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: 0.90 0.99 0.99 1/44 27222
/proc/meminfo: memFree=850508/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=3024 CPUtime=0
/proc/27222/stat : 27222 (runsolver) D 27221 27222 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 883130539 3096576 94 1283457024 134512640 134586868 4288074448 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/27222/statm: 756 94 62 19 0 54 0

[startup+0.111052 s]
/proc/loadavg: 0.90 0.99 0.99 1/44 27222
/proc/meminfo: memFree=850508/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.210767 s]
/proc/loadavg: 0.90 0.99 0.99 1/44 27222
/proc/meminfo: memFree=850508/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.310778 s]
/proc/loadavg: 0.90 0.99 0.99 1/44 27222
/proc/meminfo: memFree=850508/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.710833 s]
/proc/loadavg: 0.90 0.99 0.99 1/44 27222
/proc/meminfo: memFree=850508/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.51101 s]
/proc/loadavg: 0.90 0.99 0.99 2/46 27233
/proc/meminfo: memFree=818648/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
[pid=27233] ppid=27222 vsize=33184 CPUtime=1.44
/proc/27233/stat : 27233 (cudftodeb.nativ) R 27222 27222 4159 34819 4229 4202496 7864 0 8 0 140 4 0 0 25 0 1 0 883130542 33980416 7799 1283457024 134512640 135004320 4289599776 18446744073709551615 134951409 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27233/statm: 8296 7799 225 121 0 7688 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 35768

[startup+3.11164 s]
/proc/loadavg: 0.91 0.99 0.99 2/46 27233
/proc/meminfo: memFree=793104/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2584 CPUtime=0.02
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 566 1857 0 0 0 0 1 1 25 0 1 0 883130539 2646016 283 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 646 283 240 194 0 32 0
[pid=27233] ppid=27222 vsize=31472 CPUtime=3.04
/proc/27233/stat : 27233 (cudftodeb.nativ) R 27222 27222 4159 34819 4229 4202496 12303 0 8 0 295 9 0 0 25 0 1 0 883130542 32227328 7419 1283457024 134512640 135004320 4289599776 18446744073709551615 134950199 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27233/statm: 7868 7419 237 121 0 7260 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 34056

[startup+6.31396 s]
/proc/loadavg: 0.91 0.99 0.99 1/46 27244
/proc/meminfo: memFree=788616/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=3.44
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 694 18003 0 9 0 0 327 17 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27243] ppid=27222 vsize=47220 CPUtime=1.01
/proc/27243/stat : 27243 (aptitude) R 27222 27222 4159 34819 4229 4202496 9586 240 250 0 87 14 0 0 18 0 2 0 883130958 48353280 6134 1283457024 134512640 137933492 4291569792 18446744073709551615 4160067982 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27243/statm: 11805 6134 4185 836 0 6014 0
Current children cumulated CPU time (s) 4.45
Current children cumulated vsize (KiB) 49812
heavy processes:

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

[startup+6.40398 s]
/proc/loadavg: 0.91 0.99 0.99 2/47 27246
/proc/meminfo: memFree=778044/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=3.44
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 694 18003 0 9 0 0 327 17 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27243] ppid=27222 vsize=47220 CPUtime=1.1
/proc/27243/stat : 27243 (aptitude) R 27222 27222 4159 34819 4229 4202496 9586 240 250 0 94 16 0 0 19 0 2 0 883130958 48353280 6134 1283457024 134512640 137933492 4291569792 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27243/statm: 11805 6134 4185 836 0 6014 0
[pid=27243/tid=27245] ppid=27222 vsize=47220 CPUtime=0
/proc/27243/task/27245/stat : 27245 (aptitude) S 27222 27222 4159 34819 4229 4202560 3 240 0 0 0 0 0 0 19 0 2 0 883131145 48353280 6134 1283457024 134512640 137933492 4291569792 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920000 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.54
Current children cumulated vsize (KiB) 49812

[startup+8.01278 s]
/proc/loadavg: 0.91 0.99 0.99 2/47 27247
/proc/meminfo: memFree=775140/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=3.44
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 694 18003 0 9 0 0 327 17 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27243] ppid=27222 vsize=51556 CPUtime=2.65
/proc/27243/stat : 27243 (aptitude) R 27222 27222 4159 34819 4229 4202496 12697 1060 255 0 233 32 0 0 23 0 2 0 883130958 52793344 7465 1283457024 134512640 137933492 4291569792 18446744073709551615 4159901008 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27243/statm: 12889 7465 4433 836 0 7098 0
[pid=27243/tid=27245] ppid=27222 vsize=51556 CPUtime=0.08
/proc/27243/task/27245/stat : 27245 (aptitude) S 27222 27222 4159 34819 4229 4202560 495 1060 0 0 8 0 0 0 16 0 2 0 883131145 52793344 7465 1283457024 134512640 137933492 4291569792 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920000 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 54148

[startup+8.81178 s]
/proc/loadavg: 0.91 0.99 0.99 2/46 27249
/proc/meminfo: memFree=770460/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=6.2
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 721 31891 0 264 0 0 570 50 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27249] ppid=27222 vsize=17024 CPUtime=0.65
/proc/27249/stat : 27249 (aptsolutions.na) R 27222 27222 4159 34819 4229 4202496 3893 0 9 0 65 0 0 0 21 0 1 0 883131351 17432576 3790 1283457024 134512640 134971616 4293953888 18446744073709551615 134911543 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27249/statm: 4256 3790 204 113 0 3658 0
Current children cumulated CPU time (s) 6.85
Current children cumulated vsize (KiB) 19616

[startup+9.61194 s]
/proc/loadavg: 0.91 0.99 0.99 2/46 27249
/proc/meminfo: memFree=770460/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=6.2
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 721 31891 0 264 0 0 570 50 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27249] ppid=27222 vsize=33392 CPUtime=1.44
/proc/27249/stat : 27249 (aptsolutions.na) R 27222 27222 4159 34819 4229 4202496 7893 0 9 0 142 2 0 0 25 0 1 0 883131351 34193408 7790 1283457024 134512640 134971616 4293953888 18446744073709551615 134920783 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27249/statm: 8348 7790 204 113 0 7750 0
Current children cumulated CPU time (s) 7.64
Current children cumulated vsize (KiB) 35984

[startup+9.81198 s]
/proc/loadavg: 0.91 0.99 0.99 2/46 27249
/proc/meminfo: memFree=770460/1048576 swapFree=2077036/2097144
[pid=27222] ppid=27221 vsize=2592 CPUtime=6.2
/proc/27222/stat : 27222 (aptitude-trendy) S 27221 27222 4159 34819 4229 4202496 721 31891 0 264 0 0 570 50 18 0 1 0 883130539 2654208 294 1283457024 134512640 135304128 4294719984 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27222/statm: 648 294 249 194 0 34 0
[pid=27249] ppid=27222 vsize=44088 CPUtime=1.64
/proc/27249/stat : 27249 (aptsolutions.na) R 27222 27222 4159 34819 4229 4202496 10457 0 9 0 162 2 0 0 25 0 1 0 883131351 45146112 10352 1283457024 134512640 134971616 4293953888 18446744073709551615 134908007 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27249/statm: 11022 10352 209 113 0 10424 0
Current children cumulated CPU time (s) 7.84
Current children cumulated vsize (KiB) 46680

Child status: 0
Real time (s): 9.84893
CPU time (s): 7.88049
CPU user time (s): 7.35646
CPU system time (s): 0.524032
CPU usage (%): 80.0137
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.35646
system time used= 0.524032
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43968
page faults= 273
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 385
involuntary context switches= 227

runsolver used 0 second user time and 0 second system time

The end