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/rand994.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand994.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand994.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 1/33 12738 /proc/meminfo: memFree=932448/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=3016 CPUtime=0 /proc/12738/stat : 12738 (runsolver) D 12737 12738 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 56440869 3088384 93 1283457024 134512640 134586868 4293169040 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/12738/statm: 754 93 62 19 0 53 0 [startup+0.186016 s] /proc/loadavg: 1.00 1.02 1.00 1/33 12738 /proc/meminfo: memFree=932448/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206015 s] /proc/loadavg: 1.00 1.02 1.00 1/33 12738 /proc/meminfo: memFree=932448/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306006 s] /proc/loadavg: 1.00 1.02 1.00 1/33 12738 /proc/meminfo: memFree=932448/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.712054 s] /proc/loadavg: 1.00 1.02 1.00 1/33 12738 /proc/meminfo: memFree=932448/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.5122 s] /proc/loadavg: 1.00 1.02 1.00 2/37 12749 /proc/meminfo: memFree=913520/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=3440 CPUtime=0 /proc/12747/stat : 12747 (unclasp) S 12738 12738 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 24 0 1 0 56440873 3522560 271 1283457024 134512640 135121179 4293259760 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/12747/statm: 860 271 240 149 0 51 0 [pid=12748] ppid=12738 vsize=2692 CPUtime=0 /proc/12748/stat : 12748 (gringo) S 12738 12738 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 23 0 1 0 56440873 2756608 281 1283457024 134512640 137056543 4290175040 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/12748/statm: 673 281 252 622 0 48 0 [pid=12749] ppid=12738 vsize=28108 CPUtime=1.28 /proc/12749/stat : 12749 (cudf2lp) R 12738 12738 2160 34817 2160 4202496 7916 0 15 0 124 4 0 0 25 0 1 0 56440873 28782592 6192 1283457024 134512640 135786343 4293259760 18446744073709551615 134614240 0 0 6 0 0 0 0 17 0 0 0 0 /proc/12749/statm: 7027 6192 128 311 0 6714 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 36832 [startup+3.11253 s] /proc/loadavg: 1.00 1.02 1.00 2/37 12749 /proc/meminfo: memFree=900004/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=0 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=11056 CPUtime=0.06 /proc/12747/stat : 12747 (unclasp) S 12738 12738 2160 34817 2160 4202496 2536 0 6 0 6 0 0 0 18 0 1 0 56440873 11321344 2202 1283457024 134512640 135121179 4293259760 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/12747/statm: 2764 2202 275 149 0 1955 0 [pid=12748] ppid=12738 vsize=17024 CPUtime=0.42 /proc/12748/stat : 12748 (gringo) R 12738 12738 2160 34817 2160 4202496 4067 0 23 0 40 2 0 0 18 0 1 0 56440873 17432576 3026 1283457024 134512640 137056543 4290175040 18446744073709551615 136325066 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12748/statm: 4256 3026 253 622 0 3631 0 [pid=12749] ppid=12738 vsize=44560 CPUtime=2.38 /proc/12749/stat : 12749 (cudf2lp) R 12738 12738 2160 34817 2160 4202496 13951 0 15 0 233 5 0 0 25 0 1 0 56440873 45629440 10934 1283457024 134512640 135786343 4293259760 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/12749/statm: 11140 10934 139 311 0 10827 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 75232 [startup+6.31332 s] /proc/loadavg: 1.00 1.02 1.00 3/37 12749 /proc/meminfo: memFree=798828/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=3.02 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 15470 0 18 0 0 294 8 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=52056 CPUtime=0.19 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 14965 0 6 0 16 3 0 0 18 0 1 0 56440873 53305344 12153 1283457024 134512640 135121179 4293259760 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 13014 12153 276 149 0 12205 0 [pid=12748] ppid=12738 vsize=73872 CPUtime=2.83 /proc/12748/stat : 12748 (gringo) R 12738 12738 2160 34817 2160 4202496 24836 0 23 0 273 10 0 0 18 0 1 0 56440873 75644928 14688 1283457024 134512640 137056543 4290175040 18446744073709551615 134608504 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12748/statm: 18468 14688 268 622 0 17843 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 128520 [startup+12.7053 s] /proc/loadavg: 1.07 1.04 1.00 2/35 12749 /proc/meminfo: memFree=806424/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=128812 CPUtime=4.48 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 85571 0 7 0 413 35 0 0 25 0 1 0 56440873 131903488 29924 1283457024 134512640 135121179 4293259760 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 32203 29924 321 149 0 31394 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 131404 [startup+25.5099 s] /proc/loadavg: 1.06 1.04 1.00 2/35 12749 /proc/meminfo: memFree=806424/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=132692 CPUtime=17.27 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 332629 0 7 0 1589 138 0 0 25 0 1 0 56440873 135876608 30883 1283457024 134512640 135121179 4293259760 18446744073709551615 134981018 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 33173 30883 321 149 0 32364 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 135284 [startup+51.1081 s] /proc/loadavg: 1.04 1.03 1.00 2/35 12749 /proc/meminfo: memFree=808780/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=132696 CPUtime=42.86 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 810953 0 7 0 3933 353 0 0 25 0 1 0 56440873 135880704 30893 1283457024 134512640 135121179 4293259760 18446744073709551615 134977764 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 33174 30893 321 149 0 32365 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 135288 [startup+102.305 s] /proc/loadavg: 1.01 1.02 1.00 2/35 12749 /proc/meminfo: memFree=808532/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=131900 CPUtime=94.04 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 1765083 0 7 0 8653 751 0 0 25 0 1 0 56440873 135065600 30043 1283457024 134512640 135121179 4293259760 18446744073709551615 134992064 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 32975 30043 321 149 0 32166 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 134492 [startup+162.305 s] /proc/loadavg: 1.00 1.02 1.00 2/37 12752 /proc/meminfo: memFree=808136/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=132264 CPUtime=153.97 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 2855763 0 7 0 14239 1158 0 0 25 0 1 0 56440873 135438336 30633 1283457024 134512640 135121179 4293259760 18446744073709551615 134990484 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 33066 30633 321 149 0 32257 0 Current children cumulated CPU time (s) 161.93 Current children cumulated vsize (KiB) 134856 [startup+222.306 s] /proc/loadavg: 1.03 1.03 1.00 2/37 12758 /proc/meminfo: memFree=807268/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=129204 CPUtime=213.92 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 3910296 0 7 0 19775 1617 0 0 25 0 1 0 56440873 132304896 30008 1283457024 134512640 135121179 4293259760 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 32301 30008 321 149 0 31492 0 Current children cumulated CPU time (s) 221.88 Current children cumulated vsize (KiB) 131796 [startup+282.307 s] /proc/loadavg: 1.01 1.02 1.00 2/36 12760 /proc/meminfo: memFree=808028/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=132284 CPUtime=273.89 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 4982783 0 7 0 25297 2092 0 0 25 0 1 0 56440873 135458816 30792 1283457024 134512640 135121179 4293259760 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 33071 30792 321 149 0 32262 0 Current children cumulated CPU time (s) 281.85 Current children cumulated vsize (KiB) 134876 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.51 s] /proc/loadavg: 1.01 1.02 1.00 2/36 12760 /proc/meminfo: memFree=804308/1048576 swapFree=0/0 [pid=12738] ppid=12737 vsize=2592 CPUtime=7.96 /proc/12738/stat : 12738 (aspuncud-user-1) S 12737 12738 2160 34817 2160 4202496 573 63521 0 41 0 0 772 24 18 0 1 0 56440869 2654208 298 1283457024 134512640 135304128 4290795008 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12738/statm: 648 298 251 194 0 35 0 [pid=12747] ppid=12738 vsize=133096 CPUtime=282.09 /proc/12747/stat : 12747 (unclasp) R 12738 12738 2160 34817 2160 4202496 5129132 0 7 0 26057 2152 0 0 25 0 1 0 56440873 136290304 30948 1283457024 134512640 135121179 4293259760 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12747/statm: 33274 30948 321 149 0 32465 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 135688 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.549 CPU time (s): 290.086 CPU user time (s): 268.301 CPU system time (s): 21.7854 CPU usage (%): 99.8406 Max. virtual memory (cumulated for all children) (KiB): 247460 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.301 system time used= 21.7854 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5195618 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= 9371 involuntary context switches= 11131 runsolver used 0 second user time and 0 second system time The end