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/randea6106.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//randea6106.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randea6106.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.97 1.00 0.99 1/40 6446
/proc/meminfo: memFree=849524/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=3028 CPUtime=0
/proc/6446/stat : 6446 (runsolver) D 6445 6446 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 885568299 3100672 94 1283457024 134512640 134586868 4287259152 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/6446/statm: 757 94 62 19 0 55 0

[startup+0.109228 s]
/proc/loadavg: 0.97 1.00 0.99 1/40 6446
/proc/meminfo: memFree=849524/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.212425 s]
/proc/loadavg: 0.97 1.00 0.99 1/40 6446
/proc/meminfo: memFree=849524/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.302442 s]
/proc/loadavg: 0.97 1.00 0.99 1/40 6446
/proc/meminfo: memFree=849524/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.70252 s]
/proc/loadavg: 0.97 1.00 0.99 1/40 6446
/proc/meminfo: memFree=849524/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.50269 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6457
/proc/meminfo: memFree=817416/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
[pid=6457] ppid=6446 vsize=33680 CPUtime=1.43
/proc/6457/stat : 6457 (cudftodeb.nativ) R 6446 6446 4159 34819 4229 4202496 7949 0 8 0 140 3 0 0 25 0 1 0 885568303 34488320 7884 1283457024 134512640 135004320 4293936704 18446744073709551615 134985907 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6457/statm: 8420 7884 225 121 0 7812 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 36264

[startup+3.10316 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6457
/proc/meminfo: memFree=791748/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2584 CPUtime=0.02
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885568299 2646016 283 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 646 283 240 194 0 32 0
[pid=6457] ppid=6446 vsize=31476 CPUtime=3.03
/proc/6457/stat : 6457 (cudftodeb.nativ) R 6446 6446 4159 34819 4229 4202496 12304 0 8 0 297 6 0 0 25 0 1 0 885568303 32231424 7420 1283457024 134512640 135004320 4293936704 18446744073709551615 134855897 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6457/statm: 7869 7420 237 121 0 7261 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 34060

[startup+6.31298 s]
/proc/loadavg: 0.97 1.00 0.99 1/42 6468
/proc/meminfo: memFree=787576/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=3.42
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 693 18001 0 9 0 0 326 16 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6467] ppid=6446 vsize=47228 CPUtime=0.89
/proc/6467/stat : 6467 (aptitude) R 6446 6446 4159 34819 4229 4202496 9583 240 252 0 84 5 0 0 18 0 2 0 885568721 48361472 6135 1283457024 134512640 137933492 4286586704 18446744073709551615 4159885627 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6467/statm: 11807 6135 4185 836 0 6016 0
Current children cumulated CPU time (s) 4.31
Current children cumulated vsize (KiB) 49820
heavy processes:

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

[startup+6.40301 s]
/proc/loadavg: 0.97 1.00 0.99 2/43 6470
/proc/meminfo: memFree=776756/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=3.42
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 693 18001 0 9 0 0 326 16 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6467] ppid=6446 vsize=47228 CPUtime=0.98
/proc/6467/stat : 6467 (aptitude) R 6446 6446 4159 34819 4229 4202496 9583 240 252 0 90 8 0 0 18 0 2 0 885568721 48361472 6135 1283457024 134512640 137933492 4286586704 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6467/statm: 11807 6135 4185 836 0 6016 0
[pid=6467/tid=6469] ppid=6446 vsize=47228 CPUtime=0
/proc/6467/task/6469/stat : 6469 (aptitude) S 6446 6446 4159 34819 4229 4202560 3 240 0 0 0 0 0 0 19 0 2 0 885568916 48361472 6135 1283457024 134512640 137933492 4286586704 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393160064 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.4
Current children cumulated vsize (KiB) 49820

[startup+8.0077 s]
/proc/loadavg: 0.97 1.00 0.99 2/43 6471
/proc/meminfo: memFree=773916/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=3.42
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 693 18001 0 9 0 0 326 16 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6467] ppid=6446 vsize=50712 CPUtime=2.53
/proc/6467/stat : 6467 (aptitude) D 6446 6446 4159 34819 4229 4202496 11138 650 258 0 229 24 0 0 21 0 2 0 885568721 51929088 7208 1283457024 134512640 137933492 4286586704 18446744073709551615 4155531728 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/6467/statm: 12678 7208 4405 836 0 6887 0
[pid=6467/tid=6469] ppid=6446 vsize=50712 CPUtime=0.07
/proc/6467/task/6469/stat : 6469 (aptitude) S 6446 6446 4159 34819 4229 4202560 395 650 0 0 7 0 0 0 15 0 2 0 885568916 51929088 7208 1283457024 134512640 137933492 4286586704 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393160064 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.95
Current children cumulated vsize (KiB) 53304

[startup+8.81411 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6473
/proc/meminfo: memFree=772584/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=6.22
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 720 31796 0 268 0 0 581 41 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6473] ppid=6446 vsize=13556 CPUtime=0.48
/proc/6473/stat : 6473 (aptsolutions.na) R 6446 6446 4159 34819 4229 4202496 3038 0 9 0 48 0 0 0 21 0 1 0 885569127 13881344 2935 1283457024 134512640 134971616 4292429424 18446744073709551615 134954176 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6473/statm: 3389 2935 204 113 0 2791 0
Current children cumulated CPU time (s) 6.7
Current children cumulated vsize (KiB) 16148

[startup+9.61433 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6473
/proc/meminfo: memFree=772584/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=6.22
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 720 31796 0 268 0 0 581 41 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6473] ppid=6446 vsize=30668 CPUtime=1.28
/proc/6473/stat : 6473 (aptsolutions.na) R 6446 6446 4159 34819 4229 4202496 7249 0 9 0 128 0 0 0 24 0 1 0 885569127 31404032 7146 1283457024 134512640 134971616 4292429424 18446744073709551615 134927759 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6473/statm: 7667 7146 204 113 0 7069 0
Current children cumulated CPU time (s) 7.5
Current children cumulated vsize (KiB) 33260

[startup+9.8144 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6473
/proc/meminfo: memFree=772584/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=6.22
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 720 31796 0 268 0 0 581 41 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6473] ppid=6446 vsize=35080 CPUtime=1.48
/proc/6473/stat : 6473 (aptsolutions.na) R 6446 6446 4159 34819 4229 4202496 8358 0 9 0 147 1 0 0 25 0 1 0 885569127 35921920 8253 1283457024 134512640 134971616 4292429424 18446744073709551615 4158768677 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6473/statm: 8770 8253 208 113 0 8172 0
Current children cumulated CPU time (s) 7.7
Current children cumulated vsize (KiB) 37672

[startup+9.91444 s]
/proc/loadavg: 0.97 1.00 0.99 2/42 6473
/proc/meminfo: memFree=746304/1048576 swapFree=2077680/2097144
[pid=6446] ppid=6445 vsize=2592 CPUtime=6.22
/proc/6446/stat : 6446 (aptitude-trendy) S 6445 6446 4159 34819 4229 4202496 720 31796 0 268 0 0 581 41 18 0 1 0 885568299 2654208 294 1283457024 134512640 135304128 4294765056 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/6446/statm: 648 294 249 194 0 34 0
[pid=6473] ppid=6446 vsize=40316 CPUtime=1.58
/proc/6473/stat : 6473 (aptsolutions.na) R 6446 6446 4159 34819 4229 4202496 9621 0 9 0 157 1 0 0 25 0 1 0 885569127 41283584 9516 1283457024 134512640 134971616 4292429424 18446744073709551615 134621365 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/6473/statm: 10079 9516 209 113 0 9481 0
Current children cumulated CPU time (s) 7.8
Current children cumulated vsize (KiB) 42908

Child status: 0
Real time (s): 10.0031
CPU time (s): 7.89249
CPU user time (s): 7.44446
CPU system time (s): 0.448028
CPU usage (%): 78.9005
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.44447
system time used= 0.448028
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43939
page faults= 277
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 432
involuntary context switches= 216

runsolver used 0 second user time and 0 second system time

The end