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/rand763.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand763.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand763.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 10886 /proc/meminfo: memFree=932316/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=3020 CPUtime=0 /proc/10886/stat : 10886 (runsolver) D 10885 10886 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 55406416 3092480 94 1283457024 134512640 134586868 4292861760 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/10886/statm: 755 94 62 19 0 54 0 [startup+0.154125 s] /proc/loadavg: 1.00 1.02 1.00 2/33 10886 /proc/meminfo: memFree=932316/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206044 s] /proc/loadavg: 1.00 1.02 1.00 2/33 10886 /proc/meminfo: memFree=932316/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306032 s] /proc/loadavg: 1.00 1.02 1.00 2/33 10886 /proc/meminfo: memFree=932316/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.703655 s] /proc/loadavg: 1.00 1.02 1.00 2/33 10886 /proc/meminfo: memFree=932316/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50386 s] /proc/loadavg: 1.08 1.03 1.01 2/37 10897 /proc/meminfo: memFree=914068/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=3444 CPUtime=0 /proc/10895/stat : 10895 (unclasp) S 10886 10886 2160 34817 2160 4202496 401 0 5 0 0 0 0 0 24 0 1 0 55406421 3526656 271 1283457024 134512640 135121179 4290407072 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10895/statm: 861 271 240 149 0 52 0 [pid=10896] ppid=10886 vsize=2688 CPUtime=0 /proc/10896/stat : 10896 (gringo) S 10886 10886 2160 34817 2160 4202496 384 0 23 0 0 0 0 0 24 0 1 0 55406421 2752512 280 1283457024 134512640 137056543 4290679232 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10896/statm: 672 280 252 622 0 47 0 [pid=10897] ppid=10886 vsize=28108 CPUtime=1.27 /proc/10897/stat : 10897 (cudf2lp) R 10886 10886 2160 34817 2160 4202496 7891 0 15 0 121 6 0 0 25 0 1 0 55406421 28782592 6168 1283457024 134512640 135786343 4290412080 18446744073709551615 134633792 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10897/statm: 7027 6168 128 311 0 6714 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 36832 [startup+3.10429 s] /proc/loadavg: 1.08 1.03 1.01 2/37 10897 /proc/meminfo: memFree=900304/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=10004 CPUtime=0.02 /proc/10895/stat : 10895 (unclasp) S 10886 10886 2160 34817 2160 4202496 2253 0 6 0 2 0 0 0 18 0 1 0 55406421 10244096 1920 1283457024 134512640 135121179 4290407072 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10895/statm: 2501 1920 275 149 0 1692 0 [pid=10896] ppid=10886 vsize=12568 CPUtime=0.34 /proc/10896/stat : 10896 (gringo) R 10886 10886 2160 34817 2160 4202496 3371 0 23 0 34 0 0 0 18 0 1 0 55406421 12869632 2298 1283457024 134512640 137056543 4290679232 18446744073709551615 135715074 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10896/statm: 3142 2298 253 622 0 2517 0 [pid=10897] ppid=10886 vsize=44560 CPUtime=2.5 /proc/10897/stat : 10897 (cudf2lp) R 10886 10886 2160 34817 2160 4202496 13950 0 15 0 242 8 0 0 25 0 1 0 55406421 45629440 10934 1283457024 134512640 135786343 4290412080 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10897/statm: 11140 10934 139 311 0 10827 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 69724 [startup+6.30538 s] /proc/loadavg: 1.23 1.06 1.02 3/37 10897 /proc/meminfo: memFree=806560/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=0 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 1518 0 3 0 0 0 0 25 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=50216 CPUtime=0.3 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 14464 0 6 0 24 6 0 0 18 0 1 0 55406421 51421184 11653 1283457024 134512640 135121179 4290407072 18446744073709551615 134763664 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 12554 11653 275 149 0 11745 0 [pid=10896] ppid=10886 vsize=63248 CPUtime=2.57 /proc/10896/stat : 10896 (gringo) S 10886 10886 2160 34817 2160 4202496 21836 0 23 0 248 9 0 0 18 0 1 0 55406421 64765952 13835 1283457024 134512640 137056543 4290679232 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10896/statm: 15812 13835 253 622 0 15187 0 [pid=10897] ppid=10886 vsize=44560 CPUtime=3.18 /proc/10897/stat : 10897 (cudf2lp) R 10886 10886 2160 34817 2160 4202496 13950 0 15 0 308 10 0 0 25 0 1 0 55406421 45629440 10934 1283457024 134512640 135786343 4290412080 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10897/statm: 11140 10934 139 311 0 10827 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 160616 [startup+12.7097 s] /proc/loadavg: 1.21 1.06 1.02 2/35 10897 /proc/meminfo: memFree=804804/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=128976 CPUtime=4.19 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 85006 0 7 0 378 41 0 0 25 0 1 0 55406421 132071424 30025 1283457024 134512640 135121179 4290407072 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 32244 30025 321 149 0 31435 0 Current children cumulated CPU time (s) 12.45 Current children cumulated vsize (KiB) 131568 [startup+25.5046 s] /proc/loadavg: 1.18 1.06 1.01 2/35 10897 /proc/meminfo: memFree=808400/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=128976 CPUtime=16.97 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 314687 0 7 0 1559 138 0 0 25 0 1 0 55406421 132071424 29943 1283457024 134512640 135121179 4290407072 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 32244 29943 321 149 0 31435 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 131568 [startup+51.1118 s] /proc/loadavg: 1.11 1.05 1.01 2/35 10897 /proc/meminfo: memFree=804928/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=128980 CPUtime=42.57 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 778499 0 7 0 3931 326 0 0 25 0 1 0 55406421 132075520 29954 1283457024 134512640 135121179 4290407072 18446744073709551615 134734464 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 32245 29954 321 149 0 31436 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 131572 [startup+102.313 s] /proc/loadavg: 1.05 1.04 1.01 2/37 10903 /proc/meminfo: memFree=807880/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=129552 CPUtime=93.72 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 1671366 0 7 0 8659 713 0 0 25 0 1 0 55406421 132661248 30118 1283457024 134512640 135121179 4290407072 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 32388 30118 321 149 0 31579 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 132144 [startup+162.312 s] /proc/loadavg: 1.02 1.03 1.00 2/36 10908 /proc/meminfo: memFree=807772/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=129352 CPUtime=153.29 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 2675128 0 7 0 14176 1153 0 0 25 0 1 0 55406421 132456448 29998 1283457024 134512640 135121179 4290407072 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 32338 29998 321 149 0 31529 0 Current children cumulated CPU time (s) 161.55 Current children cumulated vsize (KiB) 131944 [startup+222.313 s] /proc/loadavg: 1.00 1.02 1.00 2/35 10908 /proc/meminfo: memFree=807656/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=133652 CPUtime=213.24 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 3684059 0 7 0 19716 1608 0 0 25 0 1 0 55406421 136859648 31137 1283457024 134512640 135121179 4290407072 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 33413 31137 321 149 0 32604 0 Current children cumulated CPU time (s) 221.5 Current children cumulated vsize (KiB) 136244 [startup+282.314 s] /proc/loadavg: 1.00 1.02 1.00 2/35 10908 /proc/meminfo: memFree=807904/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=132440 CPUtime=273.22 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 4689599 0 7 0 25275 2047 0 0 25 0 1 0 55406421 135618560 30803 1283457024 134512640 135121179 4290407072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 33110 30803 321 149 0 32301 0 Current children cumulated CPU time (s) 281.48 Current children cumulated vsize (KiB) 135032 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.906 s] /proc/loadavg: 1.00 1.02 1.00 2/35 10908 /proc/meminfo: memFree=805300/1048576 swapFree=0/0 [pid=10886] ppid=10885 vsize=2592 CPUtime=8.26 /proc/10886/stat : 10886 (aspuncud-user-1) S 10885 10886 2160 34817 2160 4202496 572 63553 0 41 0 0 798 28 18 0 1 0 55406416 2654208 297 1283457024 134512640 135304128 4287982416 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10886/statm: 648 297 251 194 0 35 0 [pid=10895] ppid=10886 vsize=132440 CPUtime=281.82 /proc/10895/stat : 10895 (unclasp) R 10886 10886 2160 34817 2160 4202496 4830808 0 7 0 26069 2113 0 0 25 0 1 0 55406421 135618560 30805 1283457024 134512640 135121179 4290407072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10895/statm: 33110 30805 321 149 0 32301 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 135032 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.947 CPU time (s): 290.106 CPU user time (s): 268.681 CPU system time (s): 21.4253 CPU usage (%): 99.7111 Max. virtual memory (cumulated for all children) (KiB): 247464 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.681 system time used= 21.4253 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 4897311 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= 9356 involuntary context switches= 11084 runsolver used 0 second user time and 0.008 second system time The end