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/rand172.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand172.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand172.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.11 1.10 1.03 3/38 3657
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=3020 CPUtime=0
/proc/3657/stat : 3657 (runsolver) D 3656 3657 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 23 0 1 0 51648658 3092480 94 1283457024 134512640 134586868 4290467072 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/3657/statm: 755 94 62 19 0 54 0

[startup+0.108718 s]
/proc/loadavg: 1.11 1.10 1.03 3/38 3657
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.2047 s]
/proc/loadavg: 1.11 1.10 1.03 3/38 3657
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.304693 s]
/proc/loadavg: 1.11 1.10 1.03 3/38 3657
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.710737 s]
/proc/loadavg: 1.11 1.10 1.03 3/38 3657
/proc/meminfo: memFree=928828/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51095 s]
/proc/loadavg: 1.10 1.10 1.03 2/42 3668
/proc/meminfo: memFree=910084/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=3440 CPUtime=0
/proc/3666/stat : 3666 (unclasp) S 3657 3657 2160 34817 2160 4202496 401 0 5 0 0 0 0 0 25 0 1 0 51648663 3522560 271 1283457024 134512640 135121179 4291325632 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3666/statm: 860 271 240 149 0 51 0
[pid=3667] ppid=3657 vsize=2696 CPUtime=0
/proc/3667/stat : 3667 (gringo) S 3657 3657 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 23 0 1 0 51648663 2760704 281 1283457024 134512640 137056543 4287892288 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3667/statm: 674 281 252 622 0 49 0
[pid=3668] ppid=3657 vsize=28116 CPUtime=1.26
/proc/3668/stat : 3668 (cudf2lp) R 3657 3657 2160 34817 2160 4202496 7917 0 15 0 126 0 0 0 25 0 1 0 51648663 28790784 6194 1283457024 134512640 135786343 4288894112 18446744073709551615 134540554 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3668/statm: 7029 6194 128 311 0 6716 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 36844

[startup+3.11144 s]
/proc/loadavg: 1.10 1.10 1.03 2/42 3668
/proc/meminfo: memFree=896196/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=0
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 1519 0 3 0 0 0 0 25 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=11188 CPUtime=0.01
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 2592 0 6 0 1 0 0 0 18 0 1 0 51648663 11456512 2259 1283457024 134512640 135121179 4291325632 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 2797 2259 275 149 0 1988 0
[pid=3667] ppid=3657 vsize=16240 CPUtime=0.44
/proc/3667/stat : 3667 (gringo) R 3657 3657 2160 34817 2160 4202496 4344 0 23 0 42 2 0 0 18 0 1 0 51648663 16629760 2758 1283457024 134512640 137056543 4287892288 18446744073709551615 134548088 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3667/statm: 4060 2758 253 622 0 3435 0
[pid=3668] ppid=3657 vsize=44568 CPUtime=2.4
/proc/3668/stat : 3668 (cudf2lp) R 3657 3657 2160 34817 2160 4202496 13951 0 15 0 236 4 0 0 25 0 1 0 51648663 45637632 10935 1283457024 134512640 135786343 4288894112 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3668/statm: 11142 10935 139 311 0 10829 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 74588

[startup+6.31207 s]
/proc/loadavg: 1.10 1.10 1.03 4/42 3668
/proc/meminfo: memFree=794392/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=2.95
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 15473 0 18 0 0 290 5 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=52588 CPUtime=0.21
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 15098 0 6 0 15 6 0 0 18 0 1 0 51648663 53850112 12287 1283457024 134512640 135121179 4291325632 18446744073709551615 134780276 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 13147 12287 276 149 0 12338 0
[pid=3667] ppid=3657 vsize=74484 CPUtime=2.89
/proc/3667/stat : 3667 (gringo) R 3657 3657 2160 34817 2160 4202496 25075 0 23 0 280 9 0 0 18 0 1 0 51648663 76271616 14895 1283457024 134512640 137056543 4287892288 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3667/statm: 18621 14895 268 622 0 17996 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 129664

[startup+12.7148 s]
/proc/loadavg: 1.16 1.11 1.04 2/40 3669
/proc/meminfo: memFree=802608/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128088 CPUtime=4.48
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 90089 0 7 0 412 36 0 0 25 0 1 0 51648663 131162112 29803 1283457024 134512640 135121179 4291325632 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32022 29803 319 149 0 31213 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 130680

[startup+25.5094 s]
/proc/loadavg: 1.13 1.11 1.03 2/40 3670
/proc/meminfo: memFree=805840/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128088 CPUtime=17.26
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 328049 0 7 0 1584 142 0 0 25 0 1 0 51648663 131162112 29723 1283457024 134512640 135121179 4291325632 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32022 29723 319 149 0 31213 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 130680

[startup+51.1094 s]
/proc/loadavg: 1.09 1.10 1.03 2/39 3670
/proc/meminfo: memFree=805112/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=133188 CPUtime=42.85
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 798020 0 7 0 3948 337 0 0 25 0 1 0 51648663 136384512 30952 1283457024 134512640 135121179 4291325632 18446744073709551615 134982663 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 33297 30952 321 149 0 32488 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 135780

[startup+102.307 s]
/proc/loadavg: 1.03 1.08 1.03 2/38 3670
/proc/meminfo: memFree=806112/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128100 CPUtime=94.01
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 1709793 0 7 0 8668 733 0 0 25 0 1 0 51648663 131174400 29755 1283457024 134512640 135121179 4291325632 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32025 29755 321 149 0 31216 0
Current children cumulated CPU time (s) 101.97
Current children cumulated vsize (KiB) 130692

[startup+162.306 s]
/proc/loadavg: 1.08 1.09 1.03 2/38 3670
/proc/meminfo: memFree=805864/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128464 CPUtime=153.6
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 2757376 0 7 0 14152 1208 0 0 25 0 1 0 51648663 131547136 29777 1283457024 134512640 135121179 4291325632 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32116 29777 321 149 0 31307 0
Current children cumulated CPU time (s) 161.56
Current children cumulated vsize (KiB) 131056

[startup+222.306 s]
/proc/loadavg: 1.03 1.07 1.03 2/38 3670
/proc/meminfo: memFree=805616/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128472 CPUtime=213.55
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 3789279 0 7 0 19679 1676 0 0 25 0 1 0 51648663 131555328 29861 1283457024 134512640 135121179 4291325632 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32118 29861 321 149 0 31309 0
Current children cumulated CPU time (s) 221.51
Current children cumulated vsize (KiB) 131064

[startup+282.308 s]
/proc/loadavg: 1.08 1.07 1.02 2/38 3670
/proc/meminfo: memFree=805120/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128476 CPUtime=273.51
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 4811442 0 7 0 25233 2118 0 0 25 0 1 0 51648663 131559424 29813 1283457024 134512640 135121179 4291325632 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32119 29813 321 149 0 31310 0
Current children cumulated CPU time (s) 281.47
Current children cumulated vsize (KiB) 131068



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.911 s]
/proc/loadavg: 1.06 1.07 1.02 3/38 3670
/proc/meminfo: memFree=804996/1048576 swapFree=0/0
[pid=3657] ppid=3656 vsize=2592 CPUtime=7.96
/proc/3657/stat : 3657 (aspuncud-user-1) S 3656 3657 2160 34817 2160 4202496 573 63554 0 41 0 0 774 22 18 0 1 0 51648658 2654208 297 1283457024 134512640 135304128 4288912448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3657/statm: 648 297 251 194 0 35 0
[pid=3666] ppid=3657 vsize=128484 CPUtime=282.1
/proc/3666/stat : 3666 (unclasp) R 3657 3657 2160 34817 2160 4202496 4955654 0 7 0 26034 2176 0 0 25 0 1 0 51648663 131567616 29880 1283457024 134512640 135121179 4291325632 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3666/statm: 32121 29880 321 149 0 31312 0
Current children cumulated CPU time (s) 290.06
Current children cumulated vsize (KiB) 131076

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.948
CPU time (s): 290.086
CPU user time (s): 268.085
CPU system time (s): 22.0014
CPU usage (%): 99.7039
Max. virtual memory (cumulated for all children) (KiB): 248520

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.085
system time used= 22.0014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5022179
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= 9370
involuntary context switches= 11107

runsolver used 0 second user time and 0.004 second system time

The end