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/201108300820/aspuncud-user-1.0/rand18.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand18.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand18.cudf.user-upgrades.result +sum(installedsize) 

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.00 1.03 1.00 1/38 4161
/proc/meminfo: memFree=928576/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=3024 CPUtime=0
/proc/4161/stat : 4161 (runsolver) D 4160 4161 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 51927830 3096576 94 1283457024 134512640 134586868 4291286464 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/4161/statm: 756 94 62 19 0 55 0

[startup+0.145761 s]
/proc/loadavg: 1.00 1.03 1.00 1/38 4161
/proc/meminfo: memFree=928576/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.205741 s]
/proc/loadavg: 1.00 1.03 1.00 1/38 4161
/proc/meminfo: memFree=928576/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.305752 s]
/proc/loadavg: 1.00 1.03 1.00 1/38 4161
/proc/meminfo: memFree=928576/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.715608 s]
/proc/loadavg: 1.00 1.03 1.00 1/38 4161
/proc/meminfo: memFree=928576/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51576 s]
/proc/loadavg: 1.00 1.03 1.00 2/42 4172
/proc/meminfo: memFree=909584/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=3444 CPUtime=0
/proc/4170/stat : 4170 (unclasp) S 4161 4161 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 51927835 3526656 271 1283457024 134512640 135121179 4288924816 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4170/statm: 861 271 240 149 0 52 0
[pid=4171] ppid=4161 vsize=2688 CPUtime=0
/proc/4171/stat : 4171 (gringo) S 4161 4161 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 23 0 1 0 51927835 2752512 280 1283457024 134512640 137056543 4288929776 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4171/statm: 672 280 252 622 0 47 0
[pid=4172] ppid=4161 vsize=28112 CPUtime=1.28
/proc/4172/stat : 4172 (cudf2lp) R 4161 4161 2160 34817 2160 4202496 7930 0 15 0 125 3 0 0 25 0 1 0 51927835 28786688 6206 1283457024 134512640 135786343 4288832272 18446744073709551615 134566144 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4172/statm: 7028 6206 128 311 0 6715 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36836

[startup+3.10609 s]
/proc/loadavg: 1.00 1.03 1.00 2/42 4172
/proc/meminfo: memFree=895572/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=0
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 1517 0 3 0 0 0 0 25 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=11640 CPUtime=0.01
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 2735 0 6 0 0 1 0 0 18 0 1 0 51927835 11919360 2310 1283457024 134512640 135121179 4288924816 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 2910 2310 275 149 0 2101 0
[pid=4171] ppid=4161 vsize=16236 CPUtime=0.47
/proc/4171/stat : 4171 (gringo) S 4161 4161 2160 34817 2160 4202496 4340 0 23 0 45 2 0 0 18 0 1 0 51927835 16625664 2786 1283457024 134512640 137056543 4288929776 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4171/statm: 4059 2786 253 622 0 3434 0
[pid=4172] ppid=4161 vsize=44564 CPUtime=2.37
/proc/4172/stat : 4172 (cudf2lp) R 4161 4161 2160 34817 2160 4202496 13952 0 15 0 233 4 0 0 25 0 1 0 51927835 45633536 10935 1283457024 134512640 135786343 4288832272 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4172/statm: 11141 10935 139 311 0 10828 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 75032

[startup+6.30713 s]
/proc/loadavg: 1.08 1.05 1.01 3/42 4173
/proc/meminfo: memFree=793956/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=3.1
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 15472 0 18 0 0 300 10 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=52460 CPUtime=0.21
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 15067 0 6 0 19 2 0 0 18 0 1 0 51927835 53719040 12255 1283457024 134512640 135121179 4288924816 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 13115 12255 276 149 0 12306 0
[pid=4171] ppid=4161 vsize=74256 CPUtime=2.74
/proc/4171/stat : 4171 (gringo) R 4161 4161 2160 34817 2160 4202496 24981 0 23 0 261 13 0 0 18 0 1 0 51927835 76038144 14833 1283457024 134512640 137056543 4288929776 18446744073709551615 134904717 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4171/statm: 18564 14833 268 622 0 17939 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 129308

[startup+12.7083 s]
/proc/loadavg: 1.07 1.05 1.00 2/40 4173
/proc/meminfo: memFree=802792/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=128612 CPUtime=4.35
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 92887 0 7 0 396 39 0 0 25 0 1 0 51927835 131698688 29879 1283457024 134512640 135121179 4288924816 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 32153 29879 321 149 0 31344 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 131204

[startup+25.5125 s]
/proc/loadavg: 1.06 1.04 1.00 2/40 4175
/proc/meminfo: memFree=805156/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=128612 CPUtime=17.15
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 342541 0 7 0 1577 138 0 0 25 0 1 0 51927835 131698688 29883 1283457024 134512640 135121179 4288924816 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 32153 29883 321 149 0 31344 0
Current children cumulated CPU time (s) 25.24
Current children cumulated vsize (KiB) 131204

[startup+51.1107 s]
/proc/loadavg: 1.04 1.04 1.00 2/39 4176
/proc/meminfo: memFree=805172/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=128616 CPUtime=42.72
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 835621 0 7 0 3924 348 0 0 25 0 1 0 51927835 131702784 29895 1283457024 134512640 135121179 4288924816 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 32154 29895 321 149 0 31345 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 131208

[startup+102.307 s]
/proc/loadavg: 1.01 1.03 1.00 2/39 4176
/proc/meminfo: memFree=805048/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=128628 CPUtime=93.89
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 1798206 0 7 0 8651 738 0 0 25 0 1 0 51927835 131715072 29916 1283457024 134512640 135121179 4288924816 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 32157 29916 321 149 0 31348 0
Current children cumulated CPU time (s) 101.98
Current children cumulated vsize (KiB) 131220

[startup+162.307 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 4176
/proc/meminfo: memFree=804808/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=128992 CPUtime=153.83
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 2903243 0 7 0 14224 1159 0 0 25 0 1 0 51927835 132087808 29937 1283457024 134512640 135121179 4288924816 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 32248 29937 321 149 0 31439 0
Current children cumulated CPU time (s) 161.92
Current children cumulated vsize (KiB) 131584

[startup+222.308 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 4176
/proc/meminfo: memFree=801088/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=132624 CPUtime=213.81
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 3991126 0 7 0 19743 1638 0 0 25 0 1 0 51927835 135806976 30822 1283457024 134512640 135121179 4288924816 18446744073709551615 134977767 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 33156 30822 321 149 0 32347 0
Current children cumulated CPU time (s) 221.9
Current children cumulated vsize (KiB) 135216

[startup+282.308 s]
/proc/loadavg: 1.00 1.01 1.00 2/38 4176
/proc/meminfo: memFree=804436/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=132084 CPUtime=273.78
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 5064003 0 7 0 25297 2081 0 0 25 0 1 0 51927835 135254016 30018 1283457024 134512640 135121179 4288924816 18446744073709551615 134990541 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 33021 30018 321 149 0 32212 0
Current children cumulated CPU time (s) 281.87
Current children cumulated vsize (KiB) 134676



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.507 s]
/proc/loadavg: 1.00 1.01 1.00 2/38 4176
/proc/meminfo: memFree=804064/1048576 swapFree=0/0
[pid=4161] ppid=4160 vsize=2592 CPUtime=8.09
/proc/4161/stat : 4161 (aspuncud-user-1) S 4160 4161 2160 34817 2160 4202496 574 63517 0 41 0 0 774 35 18 0 1 0 51927830 2654208 298 1283457024 134512640 135304128 4291643088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4161/statm: 648 298 251 194 0 35 0
[pid=4170] ppid=4161 vsize=132096 CPUtime=281.93
/proc/4170/stat : 4170 (unclasp) R 4161 4161 2160 34817 2160 4202496 5206528 0 7 0 26055 2138 0 0 25 0 1 0 51927835 135266304 30195 1283457024 134512640 135121179 4288924816 18446744073709551615 134990541 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4170/statm: 33024 30195 321 149 0 32215 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 134688

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.547
CPU time (s): 290.05
CPU user time (s): 268.305
CPU system time (s): 21.7454
CPU usage (%): 99.8291
Max. virtual memory (cumulated for all children) (KiB): 248520

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.305
system time used= 21.7454
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5273036
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 9384
involuntary context switches= 11131

runsolver used 0 second user time and 0 second system time

The end