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/rand7fec8c.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//rand7fec8c.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand7fec8c.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.29 1.14 1.04 3/45 29510
/proc/meminfo: memFree=720236/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=3264 CPUtime=0.02
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 484 0 0 0 2 0 0 0 25 0 1 0 883644177 3342336 410 1283457024 134512640 135004320 4289801600 18446744073709551615 134979173 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 816 410 224 121 0 208 0

[startup+0.209896 s]
/proc/loadavg: 1.29 1.14 1.04 3/45 29510
/proc/meminfo: memFree=720236/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=6736 CPUtime=0.19
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 1395 0 0 0 19 0 0 0 25 0 1 0 883644177 6897664 1321 1283457024 134512640 135004320 4289801600 18446744073709551615 134948159 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 1684 1321 225 121 0 1076 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 9320

[startup+0.309914 s]
/proc/loadavg: 1.29 1.14 1.04 3/45 29510
/proc/meminfo: memFree=720236/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=8968 CPUtime=0.29
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 1902 0 0 0 29 0 0 0 25 0 1 0 883644177 9183232 1828 1283457024 134512640 135004320 4289801600 18446744073709551615 134951469 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 2242 1828 225 121 0 1634 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 11552

[startup+0.409938 s]
/proc/loadavg: 1.29 1.14 1.04 3/45 29510
/proc/meminfo: memFree=720236/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=10952 CPUtime=0.39
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 2425 0 0 0 39 0 0 0 25 0 1 0 883644177 11214848 2351 1283457024 134512640 135004320 4289801600 18446744073709551615 134950022 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 2738 2351 225 121 0 2130 0
Current children cumulated CPU time (s) 0.41
Current children cumulated vsize (KiB) 13536

[startup+0.709983 s]
/proc/loadavg: 1.29 1.14 1.04 3/45 29510
/proc/meminfo: memFree=720236/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=17808 CPUtime=0.69
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 4049 0 0 0 67 2 0 0 25 0 1 0 883644177 18235392 3975 1283457024 134512640 135004320 4289801600 18446744073709551615 134826044 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 4452 3975 225 121 0 3844 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 20392

[startup+1.51011 s]
/proc/loadavg: 1.27 1.14 1.04 2/46 29511
/proc/meminfo: memFree=695692/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=33928 CPUtime=1.49
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 8026 0 0 0 144 5 0 0 25 0 1 0 883644177 34742272 7952 1283457024 134512640 135004320 4289801600 18446744073709551615 134961079 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 8482 7952 225 121 0 7874 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 36512

[startup+3.1104 s]
/proc/loadavg: 1.27 1.14 1.04 2/46 29511
/proc/meminfo: memFree=670644/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2584 CPUtime=0.02
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 567 1862 0 0 0 0 0 2 25 0 1 0 883644175 2646016 283 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 646 283 240 194 0 32 0
[pid=29510] ppid=29500 vsize=31472 CPUtime=3.09
/proc/29510/stat : 29510 (cudftodeb.nativ) R 29500 29500 4159 34819 4229 4202496 12312 0 0 0 302 7 0 0 25 0 1 0 883644177 32227328 7419 1283457024 134512640 135004320 4289801600 18446744073709551615 134864940 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29510/statm: 7868 7419 237 121 0 7260 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 34056

[startup+6.30948 s]
/proc/loadavg: 1.33 1.15 1.05 2/46 29522
/proc/meminfo: memFree=672188/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=3.48
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 691 18009 0 1 0 0 332 16 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29521] ppid=29500 vsize=47220 CPUtime=1.31
/proc/29521/stat : 29521 (aptitude) R 29500 29500 4159 34819 4229 4202496 9657 241 177 0 116 15 0 0 19 0 2 0 883644606 48353280 6134 1283457024 134512640 137933492 4294411744 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29521/statm: 11805 6134 4185 836 0 6014 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 49812
heavy processes:

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

[startup+6.50953 s]
/proc/loadavg: 1.33 1.15 1.05 2/47 29524
/proc/meminfo: memFree=666352/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=3.48
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 691 18009 0 1 0 0 332 16 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29521] ppid=29500 vsize=47220 CPUtime=1.5
/proc/29521/stat : 29521 (aptitude) R 29500 29500 4159 34819 4229 4202496 9657 241 177 0 132 18 0 0 19 0 2 0 883644606 48353280 6134 1283457024 134512640 137933492 4294411744 18446744073709551615 4159934524 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29521/statm: 11805 6134 4185 836 0 6014 0
[pid=29521/tid=29523] ppid=29500 vsize=47220 CPUtime=0
/proc/29521/task/29523/stat : 29523 (aptitude) S 29500 29500 4159 34819 4229 4202560 3 241 0 0 0 0 0 0 19 0 2 0 883644759 48353280 6134 1283457024 134512640 137933492 4294411744 18446744073709551615 4294960130 0 134217728 4096 0 18446612133055118400 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.98
Current children cumulated vsize (KiB) 49812

[startup+8.10996 s]
/proc/loadavg: 1.33 1.15 1.05 3/46 29527
/proc/meminfo: memFree=672064/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=6.22
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 719 31679 0 178 0 0 579 43 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29527] ppid=29500 vsize=10912 CPUtime=0.37
/proc/29527/stat : 29527 (aptsolutions.na) R 29500 29500 4159 34819 4229 4202496 2430 0 0 0 37 0 0 0 22 0 1 0 883644948 11173888 2317 1283457024 134512640 134971616 4294660624 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29527/statm: 2728 2317 204 113 0 2130 0
Current children cumulated CPU time (s) 6.59
Current children cumulated vsize (KiB) 13504

[startup+8.91296 s]
/proc/loadavg: 1.33 1.15 1.05 2/46 29527
/proc/meminfo: memFree=649000/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=6.22
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 719 31679 0 178 0 0 579 43 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29527] ppid=29500 vsize=28184 CPUtime=1.17
/proc/29527/stat : 29527 (aptsolutions.na) R 29500 29500 4159 34819 4229 4202496 6624 0 0 0 116 1 0 0 25 0 1 0 883644948 28860416 6511 1283457024 134512640 134971616 4294660624 18446744073709551615 134915842 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29527/statm: 7046 6511 204 113 0 6448 0
Current children cumulated CPU time (s) 7.39
Current children cumulated vsize (KiB) 30776

[startup+9.31306 s]
/proc/loadavg: 1.33 1.15 1.05 2/46 29527
/proc/meminfo: memFree=649000/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=6.22
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 719 31679 0 178 0 0 579 43 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29527] ppid=29500 vsize=39064 CPUtime=1.57
/proc/29527/stat : 29527 (aptsolutions.na) R 29500 29500 4159 34819 4229 4202496 9341 0 0 0 155 2 0 0 25 0 1 0 883644948 40001536 9226 1283457024 134512640 134971616 4294660624 18446744073709551615 134526251 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29527/statm: 9766 9226 209 113 0 9168 0
Current children cumulated CPU time (s) 7.79
Current children cumulated vsize (KiB) 41656

[startup+9.41316 s]
/proc/loadavg: 1.33 1.15 1.05 2/46 29527
/proc/meminfo: memFree=649000/1048576 swapFree=2077628/2097144
[pid=29500] ppid=29499 vsize=2592 CPUtime=6.22
/proc/29500/stat : 29500 (aptitude-trendy) S 29499 29500 4159 34819 4229 4202496 719 31679 0 178 0 0 579 43 18 0 1 0 883644175 2654208 294 1283457024 134512640 135304128 4286833264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29500/statm: 648 294 249 194 0 34 0
[pid=29527] ppid=29500 vsize=48828 CPUtime=1.67
/proc/29527/stat : 29527 (aptsolutions.na) R 29500 29500 4159 34819 4229 4202496 11138 0 0 0 165 2 0 0 25 0 1 0 883644948 49999872 11023 1283457024 134512640 134971616 4294660624 18446744073709551615 134912795 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29527/statm: 12207 11023 209 113 0 11609 0
Current children cumulated CPU time (s) 7.89
Current children cumulated vsize (KiB) 51420

Child status: 0
Real time (s): 9.42699
CPU time (s): 7.91649
CPU user time (s): 7.45246
CPU system time (s): 0.464029
CPU usage (%): 83.9769
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.45247
system time used= 0.464029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43883
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= 232
involuntary context switches= 221

runsolver used 0 second user time and 0 second system time

The end