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/rand740.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand740.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand740.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.04 1.01 1/33 10370 /proc/meminfo: memFree=929400/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=3024 CPUtime=0 /proc/10370/stat : 10370 (runsolver) D 10369 10370 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 55125490 3096576 94 1283457024 134512640 134586868 4293019504 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/10370/statm: 756 94 62 19 0 55 0 [startup+0.120683 s] /proc/loadavg: 1.00 1.04 1.01 1/33 10370 /proc/meminfo: memFree=929400/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.204706 s] /proc/loadavg: 1.00 1.04 1.01 1/33 10370 /proc/meminfo: memFree=929400/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.308711 s] /proc/loadavg: 1.00 1.04 1.01 1/33 10370 /proc/meminfo: memFree=929400/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.708772 s] /proc/loadavg: 1.00 1.04 1.01 1/33 10370 /proc/meminfo: memFree=929400/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.5103 s] /proc/loadavg: 1.00 1.04 1.01 2/37 10381 /proc/meminfo: memFree=910348/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=3448 CPUtime=0 /proc/10379/stat : 10379 (unclasp) S 10370 10370 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 24 0 1 0 55125495 3530752 272 1283457024 134512640 135121179 4291687136 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10379/statm: 862 272 240 149 0 53 0 [pid=10380] ppid=10370 vsize=2688 CPUtime=0 /proc/10380/stat : 10380 (gringo) S 10370 10370 2160 34817 2160 4202496 386 0 22 0 0 0 0 0 24 0 1 0 55125495 2752512 280 1283457024 134512640 137056543 4289724336 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10380/statm: 672 280 252 622 0 47 0 [pid=10381] ppid=10370 vsize=28108 CPUtime=1.28 /proc/10381/stat : 10381 (cudf2lp) R 10370 10370 2160 34817 2160 4202496 7926 0 15 0 126 2 0 0 25 0 1 0 55125495 28782592 6202 1283457024 134512640 135786343 4291694080 18446744073709551615 134850462 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10381/statm: 7027 6202 128 311 0 6714 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 36836 [startup+3.11082 s] /proc/loadavg: 1.00 1.04 1.01 2/37 10381 /proc/meminfo: memFree=896460/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=0 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 1515 0 3 0 0 0 0 25 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=11460 CPUtime=0.03 /proc/10379/stat : 10379 (unclasp) S 10370 10370 2160 34817 2160 4202496 2639 0 6 0 3 0 0 0 18 0 1 0 55125495 11735040 2305 1283457024 134512640 135121179 4291687136 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/10379/statm: 2865 2305 275 149 0 2056 0 [pid=10380] ppid=10370 vsize=16236 CPUtime=0.44 /proc/10380/stat : 10380 (gringo) R 10370 10370 2160 34817 2160 4202496 4339 0 22 0 41 3 0 0 18 0 1 0 55125495 16625664 2784 1283457024 134512640 137056543 4289724336 18446744073709551615 134608568 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10380/statm: 4059 2784 253 622 0 3434 0 [pid=10381] ppid=10370 vsize=44560 CPUtime=2.42 /proc/10381/stat : 10381 (cudf2lp) R 10370 10370 2160 34817 2160 4202496 13951 0 15 0 238 4 0 0 25 0 1 0 55125495 45629440 10934 1283457024 134512640 135786343 4291694080 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/10381/statm: 11140 10934 139 311 0 10827 0 Current children cumulated CPU time (s) 2.89 Current children cumulated vsize (KiB) 74848 [startup+6.31166 s] /proc/loadavg: 1.00 1.04 1.01 4/37 10381 /proc/meminfo: memFree=794532/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=3.2 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 15469 0 18 0 0 311 9 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=53140 CPUtime=0.16 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 15254 0 6 0 12 4 0 0 18 0 1 0 55125495 54415360 12442 1283457024 134512640 135121179 4291687136 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 13285 12442 276 149 0 12476 0 [pid=10380] ppid=10370 vsize=74996 CPUtime=2.71 /proc/10380/stat : 10380 (gringo) R 10370 10370 2160 34817 2160 4202496 25167 0 22 0 257 14 0 0 18 0 1 0 55125495 76795904 15018 1283457024 134512640 137056543 4289724336 18446744073709551615 136246242 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10380/statm: 18749 15018 268 622 0 18124 0 Current children cumulated CPU time (s) 6.07 Current children cumulated vsize (KiB) 130728 [startup+12.7145 s] /proc/loadavg: 1.00 1.04 1.01 2/35 10381 /proc/meminfo: memFree=805856/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=129088 CPUtime=4.56 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 90344 0 7 0 421 35 0 0 25 0 1 0 55125495 132186112 29970 1283457024 134512640 135121179 4291687136 18446744073709551615 134713280 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32272 29970 321 149 0 31463 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 131680 [startup+25.509 s] /proc/loadavg: 1.00 1.04 1.01 2/35 10381 /proc/meminfo: memFree=804368/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=131596 CPUtime=17.33 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 325659 0 7 0 1586 147 0 0 25 0 1 0 55125495 134754304 30607 1283457024 134512640 135121179 4291687136 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32899 30607 321 149 0 32090 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 134188 [startup+51.1076 s] /proc/loadavg: 1.00 1.03 1.00 2/35 10381 /proc/meminfo: memFree=806104/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=129092 CPUtime=42.91 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 790178 0 7 0 3943 348 0 0 25 0 1 0 55125495 132190208 29992 1283457024 134512640 135121179 4291687136 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32273 29992 321 149 0 31464 0 Current children cumulated CPU time (s) 50.81 Current children cumulated vsize (KiB) 131684 [startup+102.307 s] /proc/loadavg: 1.00 1.03 1.00 2/37 10387 /proc/meminfo: memFree=803228/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=131608 CPUtime=94.08 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 1692807 0 7 0 8666 742 0 0 25 0 1 0 55125495 134766592 30640 1283457024 134512640 135121179 4291687136 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32902 30640 321 149 0 32093 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 134200 [startup+162.309 s] /proc/loadavg: 1.00 1.02 1.00 2/36 10392 /proc/meminfo: memFree=803120/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=131976 CPUtime=154.02 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 2727174 0 7 0 14277 1125 0 0 25 0 1 0 55125495 135143424 30138 1283457024 134512640 135121179 4291687136 18446744073709551615 134990446 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32994 30138 321 149 0 32185 0 Current children cumulated CPU time (s) 161.92 Current children cumulated vsize (KiB) 134568 [startup+222.311 s] /proc/loadavg: 1.00 1.01 1.00 2/35 10392 /proc/meminfo: memFree=802384/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=131988 CPUtime=213.93 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 3739481 0 7 0 19858 1535 0 0 25 0 1 0 55125495 135155712 30469 1283457024 134512640 135121179 4291687136 18446744073709551615 134990446 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32997 30469 321 149 0 32188 0 Current children cumulated CPU time (s) 221.83 Current children cumulated vsize (KiB) 134580 [startup+282.307 s] /proc/loadavg: 1.00 1.01 1.00 2/36 10396 /proc/meminfo: memFree=804676/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=128916 CPUtime=273.78 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 4722261 0 7 0 25414 1964 0 0 25 0 1 0 55125495 132009984 29931 1283457024 134512640 135121179 4291687136 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32229 29931 321 149 0 31420 0 Current children cumulated CPU time (s) 281.68 Current children cumulated vsize (KiB) 131508 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.71 s] /proc/loadavg: 1.00 1.01 1.00 2/35 10396 /proc/meminfo: memFree=804684/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=128916 CPUtime=282.16 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 4860909 0 7 0 26193 2023 0 0 25 0 1 0 55125495 132009984 29997 1283457024 134512640 135121179 4291687136 18446744073709551615 4159837253 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32229 29997 321 149 0 31420 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 131508 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.71 s] /proc/loadavg: 1.00 1.01 1.00 2/35 10396 /proc/meminfo: memFree=804684/1048576 swapFree=0/0 [pid=10370] ppid=10369 vsize=2592 CPUtime=7.9 /proc/10370/stat : 10370 (aspuncud-user-1) S 10369 10370 2160 34817 2160 4202496 574 63518 0 40 0 0 752 38 18 0 1 0 55125490 2654208 298 1283457024 134512640 135304128 4290414000 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/10370/statm: 648 298 251 194 0 35 0 [pid=10379] ppid=10370 vsize=128916 CPUtime=282.16 /proc/10379/stat : 10379 (unclasp) R 10370 10370 2160 34817 2160 4202496 4860909 0 7 0 26193 2023 0 0 25 0 1 0 55125495 132009984 29997 1283457024 134512640 135121179 4291687136 18446744073709551615 4159837253 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/10379/statm: 32229 29997 321 149 0 31420 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 131508 Child status: 0 Real time (s): 290.749 CPU time (s): 290.102 CPU user time (s): 269.465 CPU system time (s): 20.6373 CPU usage (%): 99.7774 Max. virtual memory (cumulated for all children) (KiB): 249428 getrusage(RUSAGE_CHILDREN,...) data: user time used= 269.465 system time used= 20.6373 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 4927395 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= 9332 involuntary context switches= 11114 runsolver used 0 second user time and 0 second system time The end