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/rand152.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand152.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand152.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.02 1.00 2/33 3083
/proc/meminfo: memFree=932020/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=3024 CPUtime=0
/proc/3083/stat : 3083 (runsolver) D 3082 3083 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 51359850 3096576 94 1283457024 134512640 134586868 4290311376 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/3083/statm: 756 94 62 19 0 55 0

[startup+0.127767 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 3083
/proc/meminfo: memFree=932020/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207792 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 3083
/proc/meminfo: memFree=932020/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.317109 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 3083
/proc/meminfo: memFree=932020/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.707189 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 3083
/proc/meminfo: memFree=932020/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51738 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 3094
/proc/meminfo: memFree=913408/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=3448 CPUtime=0
/proc/3092/stat : 3092 (unclasp) S 3083 3083 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 25 0 1 0 51359855 3530752 272 1283457024 134512640 135121179 4294792624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3092/statm: 862 272 240 149 0 53 0
[pid=3093] ppid=3083 vsize=2696 CPUtime=0
/proc/3093/stat : 3093 (gringo) S 3083 3083 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 51359855 2760704 281 1283457024 134512640 137056543 4290723024 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3093/statm: 674 281 252 622 0 49 0
[pid=3094] ppid=3083 vsize=28112 CPUtime=1.28
/proc/3094/stat : 3094 (cudf2lp) R 3083 3083 2160 34817 2160 4202496 7913 0 15 0 125 3 0 0 25 0 1 0 51359855 28786688 6189 1283457024 134512640 135786343 4294795184 18446744073709551615 135052821 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3094/statm: 7028 6189 128 311 0 6715 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36848

[startup+3.10775 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 3094
/proc/meminfo: memFree=899644/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=10800 CPUtime=0.03
/proc/3092/stat : 3092 (unclasp) S 3083 3083 2160 34817 2160 4202496 2477 0 6 0 3 0 0 0 18 0 1 0 51359855 11059200 2143 1283457024 134512640 135121179 4294792624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3092/statm: 2700 2143 275 149 0 1891 0
[pid=3093] ppid=3083 vsize=12828 CPUtime=0.37
/proc/3093/stat : 3093 (gringo) R 3083 3083 2160 34817 2160 4202496 3531 0 23 0 34 3 0 0 18 0 1 0 51359855 13135872 2490 1283457024 134512640 137056543 4290723024 18446744073709551615 135855982 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3093/statm: 3207 2490 253 622 0 2582 0
[pid=3094] ppid=3083 vsize=44564 CPUtime=2.46
/proc/3094/stat : 3094 (cudf2lp) R 3083 3083 2160 34817 2160 4202496 13952 0 15 0 240 6 0 0 25 0 1 0 51359855 45633536 10935 1283457024 134512640 135786343 4294795184 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3094/statm: 11141 10935 139 311 0 10828 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 70784

[startup+6.30834 s]
/proc/loadavg: 1.08 1.04 1.01 3/37 3094
/proc/meminfo: memFree=800136/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=0
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=51668 CPUtime=0.18
/proc/3092/stat : 3092 (unclasp) S 3083 3083 2160 34817 2160 4202496 14872 0 6 0 14 4 0 0 18 0 1 0 51359855 52908032 12060 1283457024 134512640 135121179 4294792624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3092/statm: 12917 12060 275 149 0 12108 0
[pid=3093] ppid=3083 vsize=72108 CPUtime=2.81
/proc/3093/stat : 3093 (gringo) S 3083 3083 2160 34817 2160 4202496 24282 0 23 0 269 12 0 0 18 0 1 0 51359855 73838592 14263 1283457024 134512640 137056543 4290723024 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3093/statm: 18027 14263 253 622 0 17402 0
[pid=3094] ppid=3083 vsize=24736 CPUtime=3.05
/proc/3094/stat : 3094 (cudf2lp) R 3083 3083 2160 34817 2160 4202496 13952 0 15 0 297 8 0 0 25 0 1 0 51359855 25329664 6008 1283457024 134512640 135786343 4294795184 18446744073709551615 135195341 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3094/statm: 6184 6008 139 311 0 5871 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 151104

[startup+12.711 s]
/proc/loadavg: 1.07 1.04 1.00 2/37 3096
/proc/meminfo: memFree=808528/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=131492 CPUtime=4.37
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 90663 0 7 0 401 36 0 0 25 0 1 0 51359855 134647808 30127 1283457024 134512640 135121179 4294792624 18446744073709551615 134992074 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32873 30127 321 149 0 32064 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 134084

[startup+25.5153 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 3097
/proc/meminfo: memFree=808528/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=128424 CPUtime=17.17
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 341931 0 7 0 1587 130 0 0 25 0 1 0 51359855 131506176 29837 1283457024 134512640 135121179 4294792624 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32106 29837 321 149 0 31297 0
Current children cumulated CPU time (s) 25.24
Current children cumulated vsize (KiB) 131016

[startup+51.1044 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 3100
/proc/meminfo: memFree=808404/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=128428 CPUtime=42.74
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 835165 0 7 0 3936 338 0 0 25 0 1 0 51359855 131510272 29848 1283457024 134512640 135121179 4294792624 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32107 29848 321 149 0 31298 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 131020

[startup+102.303 s]
/proc/loadavg: 1.01 1.02 1.00 2/37 3105
/proc/meminfo: memFree=807908/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=128800 CPUtime=93.9
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 1803575 0 7 0 8672 718 0 0 25 0 1 0 51359855 131891200 29915 1283457024 134512640 135121179 4294792624 18446744073709551615 134890917 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32200 29915 321 149 0 31391 0
Current children cumulated CPU time (s) 101.97
Current children cumulated vsize (KiB) 131392

[startup+162.315 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 3105
/proc/meminfo: memFree=807924/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=132236 CPUtime=153.86
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 2909428 0 7 0 14218 1168 0 0 25 0 1 0 51359855 135409664 30715 1283457024 134512640 135121179 4294792624 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 33059 30715 321 149 0 32250 0
Current children cumulated CPU time (s) 161.93
Current children cumulated vsize (KiB) 134828

[startup+222.315 s]
/proc/loadavg: 1.07 1.03 1.00 2/40 3164
/proc/meminfo: memFree=797288/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=129176 CPUtime=213.59
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 3997786 0 7 0 19744 1615 0 0 25 0 1 0 51359855 132276224 29951 1283457024 134512640 135121179 4294792624 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32294 29951 321 149 0 31485 0
Current children cumulated CPU time (s) 221.66
Current children cumulated vsize (KiB) 131768

[startup+282.307 s]
/proc/loadavg: 1.02 1.02 1.00 2/38 3164
/proc/meminfo: memFree=797684/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=129180 CPUtime=273.53
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 5079377 0 7 0 25303 2050 0 0 25 0 1 0 51359855 132280320 29978 1283457024 134512640 135121179 4294792624 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32295 29978 321 149 0 31486 0
Current children cumulated CPU time (s) 281.6
Current children cumulated vsize (KiB) 131772



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.71 s]
/proc/loadavg: 1.02 1.02 1.00 2/38 3164
/proc/meminfo: memFree=797560/1048576 swapFree=0/0
[pid=3083] ppid=3082 vsize=2592 CPUtime=8.07
/proc/3083/stat : 3083 (aspuncud-user-1) S 3082 3083 2160 34817 2160 4202496 574 63519 0 41 0 0 778 29 18 0 1 0 51359850 2654208 298 1283457024 134512640 135304128 4290192752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3083/statm: 648 298 251 194 0 35 0
[pid=3092] ppid=3083 vsize=129192 CPUtime=281.94
/proc/3092/stat : 3092 (unclasp) R 3083 3083 2160 34817 2160 4202496 5231188 0 7 0 26096 2098 0 0 25 0 1 0 51359855 132292608 29990 1283457024 134512640 135121179 4294792624 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3092/statm: 32298 29990 321 149 0 31489 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 131784

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.749
CPU time (s): 290.03
CPU user time (s): 268.741
CPU system time (s): 21.2893
CPU usage (%): 99.7528
Max. virtual memory (cumulated for all children) (KiB): 249436

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.741
system time used= 21.2893
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5297691
page faults= 49
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= 11574

runsolver used 0 second user time and 0 second system time

The end