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/rand519.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand519.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand519.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.01 1.00 3/37 8309
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=3016 CPUtime=0
/proc/8309/stat : 8309 (runsolver) D 8308 8309 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 23 0 1 0 54073509 3088384 93 1283457024 134512640 134586868 4294713600 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/8309/statm: 754 93 62 19 0 53 0

[startup+0.199477 s]
/proc/loadavg: 1.00 1.01 1.00 3/37 8309
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207494 s]
/proc/loadavg: 1.00 1.01 1.00 3/37 8309
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.311002 s]
/proc/loadavg: 1.00 1.01 1.00 3/37 8309
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.71107 s]
/proc/loadavg: 1.00 1.01 1.00 3/37 8309
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5112 s]
/proc/loadavg: 1.00 1.01 1.00 2/41 8320
/proc/meminfo: memFree=909776/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=3444 CPUtime=0
/proc/8318/stat : 8318 (unclasp) S 8309 8309 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 24 0 1 0 54073513 3526656 272 1283457024 134512640 135121179 4291519200 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8318/statm: 861 272 240 149 0 52 0
[pid=8319] ppid=8309 vsize=2692 CPUtime=0
/proc/8319/stat : 8319 (gringo) S 8309 8309 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 23 0 1 0 54073513 2756608 281 1283457024 134512640 137056543 4288149296 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8319/statm: 673 281 252 622 0 48 0
[pid=8320] ppid=8309 vsize=28116 CPUtime=1.27
/proc/8320/stat : 8320 (cudf2lp) R 8309 8309 2160 34817 2160 4202496 7924 0 15 0 122 5 0 0 25 0 1 0 54073513 28790784 6200 1283457024 134512640 135786343 4291516048 18446744073709551615 134566170 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8320/statm: 7029 6200 128 311 0 6716 0
Current children cumulated CPU time (s) 1.27
Current children cumulated vsize (KiB) 36844

[startup+3.1115 s]
/proc/loadavg: 1.00 1.01 1.00 2/41 8320
/proc/meminfo: memFree=895888/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=0
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 1515 0 3 0 0 0 0 25 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=11456 CPUtime=0.05
/proc/8318/stat : 8318 (unclasp) S 8309 8309 2160 34817 2160 4202496 2639 0 6 0 5 0 0 0 18 0 1 0 54073513 11730944 2305 1283457024 134512640 135121179 4291519200 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8318/statm: 2864 2305 275 149 0 2055 0
[pid=8319] ppid=8309 vsize=16240 CPUtime=0.39
/proc/8319/stat : 8319 (gringo) R 8309 8309 2160 34817 2160 4202496 4337 0 23 0 38 1 0 0 18 0 1 0 54073513 16629760 2783 1283457024 134512640 137056543 4288149296 18446744073709551615 134608568 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8319/statm: 4060 2783 253 622 0 3435 0
[pid=8320] ppid=8309 vsize=44568 CPUtime=2.43
/proc/8320/stat : 8320 (cudf2lp) R 8309 8309 2160 34817 2160 4202496 13952 0 15 0 238 5 0 0 25 0 1 0 54073513 45637632 10935 1283457024 134512640 135786343 4291516048 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8320/statm: 11142 10935 139 311 0 10829 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 74856

[startup+6.31214 s]
/proc/loadavg: 1.08 1.02 1.01 3/41 8320
/proc/meminfo: memFree=794332/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=3.03
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 15470 0 18 0 0 296 7 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=52720 CPUtime=0.2
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 15141 0 6 0 16 4 0 0 18 0 1 0 54073513 53985280 12329 1283457024 134512640 135121179 4291519200 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 13180 12329 276 149 0 12371 0
[pid=8319] ppid=8309 vsize=74476 CPUtime=2.82
/proc/8319/stat : 8319 (gringo) R 8309 8309 2160 34817 2160 4202496 25063 0 23 0 273 9 0 0 18 0 1 0 54073513 76263424 14915 1283457024 134512640 137056543 4288149296 18446744073709551615 134608465 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8319/statm: 18619 14915 268 622 0 17994 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 129788

[startup+12.714 s]
/proc/loadavg: 1.07 1.02 1.00 2/38 8320
/proc/meminfo: memFree=801944/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=128608 CPUtime=4.56
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 90840 0 7 0 426 30 0 0 25 0 1 0 54073513 131694592 29874 1283457024 134512640 135121179 4291519200 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 32152 29874 321 149 0 31343 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 131200

[startup+25.5086 s]
/proc/loadavg: 1.06 1.02 1.00 2/38 8320
/proc/meminfo: memFree=801944/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=134008 CPUtime=17.35
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 340331 0 7 0 1595 140 0 0 25 0 1 0 54073513 137224192 31100 1283457024 134512640 135121179 4291519200 18446744073709551615 4157991702 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 33502 31100 321 149 0 32693 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 136600

[startup+51.1078 s]
/proc/loadavg: 1.04 1.02 1.00 2/38 8320
/proc/meminfo: memFree=802936/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=134016 CPUtime=42.91
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 831626 0 7 0 3943 348 0 0 25 0 1 0 54073513 137232384 31191 1283457024 134512640 135121179 4291519200 18446744073709551615 4157991702 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 33504 31191 321 149 0 32695 0
Current children cumulated CPU time (s) 50.82
Current children cumulated vsize (KiB) 136608

[startup+102.306 s]
/proc/loadavg: 1.01 1.02 1.00 2/38 8320
/proc/meminfo: memFree=805168/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=128624 CPUtime=94.05
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 1784990 0 7 0 8665 740 0 0 25 0 1 0 54073513 131710976 29900 1283457024 134512640 135121179 4291519200 18446744073709551615 4159525957 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 32156 29900 321 149 0 31347 0
Current children cumulated CPU time (s) 101.96
Current children cumulated vsize (KiB) 131216

[startup+162.308 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 8323
/proc/meminfo: memFree=803408/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=128988 CPUtime=153.99
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 2878790 0 7 0 14187 1212 0 0 25 0 1 0 54073513 132083712 29936 1283457024 134512640 135121179 4291519200 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 32247 29936 321 149 0 31438 0
Current children cumulated CPU time (s) 161.9
Current children cumulated vsize (KiB) 131580

[startup+222.31 s]
/proc/loadavg: 1.00 1.00 1.00 2/40 8329
/proc/meminfo: memFree=804648/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=129000 CPUtime=213.94
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 3958211 0 7 0 19722 1672 0 0 25 0 1 0 54073513 132096000 29958 1283457024 134512640 135121179 4291519200 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 32250 29958 321 149 0 31441 0
Current children cumulated CPU time (s) 221.85
Current children cumulated vsize (KiB) 131592

[startup+282.311 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 8331
/proc/meminfo: memFree=800944/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=129004 CPUtime=273.87
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 5024350 0 7 0 25241 2146 0 0 25 0 1 0 54073513 132100096 29974 1283457024 134512640 135121179 4291519200 18446744073709551615 134713294 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 32251 29974 321 149 0 31442 0
Current children cumulated CPU time (s) 281.78
Current children cumulated vsize (KiB) 131596



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.612 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 8331
/proc/meminfo: memFree=801936/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=132080 CPUtime=282.17
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 5173066 0 7 0 26002 2215 0 0 25 0 1 0 54073513 135249920 30745 1283457024 134512640 135121179 4291519200 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 33020 30745 321 149 0 32211 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 134672

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

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

[startup+290.612 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 8331
/proc/meminfo: memFree=801936/1048576 swapFree=0/0
[pid=8309] ppid=8308 vsize=2592 CPUtime=7.91
/proc/8309/stat : 8309 (aspuncud-user-1) S 8308 8309 2160 34817 2160 4202496 573 63518 0 41 0 0 762 29 18 0 1 0 54073509 2654208 298 1283457024 134512640 135304128 4291139168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8309/statm: 648 298 251 194 0 35 0
[pid=8318] ppid=8309 vsize=132080 CPUtime=282.17
/proc/8318/stat : 8318 (unclasp) R 8309 8309 2160 34817 2160 4202496 5173066 0 7 0 26002 2215 0 0 25 0 1 0 54073513 135249920 30745 1283457024 134512640 135121179 4291519200 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8318/statm: 33020 30745 321 149 0 32211 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 134672

Child status: 0
Real time (s): 290.648
CPU time (s): 290.11
CPU user time (s): 267.653
CPU system time (s): 22.4574
CPU usage (%): 99.815
Max. virtual memory (cumulated for all children) (KiB): 249148

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 267.653
system time used= 22.4574
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5239571
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= 9349
involuntary context switches= 11088

runsolver used 0 second user time and 0 second system time

The end