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/201108311143/aspuncud-user-1.0/rand796.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand796.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/rand796.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.01 1.04 1.01 5/38 29207 /proc/meminfo: memFree=694796/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2584 CPUtime=0 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 65328302 2646016 279 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/29204/statm: 646 279 234 194 0 33 0 [pid=29205] ppid=29204 vsize=2584 CPUtime=0 /proc/29205/stat : 29205 (aspuncud-user-1) S 29204 29204 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 18 0 1 0 65328302 2646016 133 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/29205/statm: 646 133 87 194 0 33 0 [pid=29206] ppid=29205 vsize=2584 CPUtime=0 /proc/29206/stat : 29206 (aspuncud-user-1) R 29205 29204 19908 34817 19908 4202560 126 0 0 0 0 0 0 0 25 0 1 0 65328302 2646016 150 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29206/statm: 646 150 104 194 0 33 0 [pid=29207] ppid=29206 vsize=2584 CPUtime=0 /proc/29207/stat : 29207 (aspuncud-user-1) R 29206 29204 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65328302 2646016 46 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29207/statm: 646 46 0 194 0 33 0 [startup+0.126837 s] /proc/loadavg: 1.01 1.04 1.01 5/38 29207 /proc/meminfo: memFree=694796/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=0.01 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 575 1519 0 0 0 1 0 0 25 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2588 [startup+0.206848 s] /proc/loadavg: 1.01 1.04 1.01 5/38 29207 /proc/meminfo: memFree=694796/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=0.01 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 575 1519 0 0 0 1 0 0 25 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2588 [startup+0.306866 s] /proc/loadavg: 1.01 1.04 1.01 5/38 29207 /proc/meminfo: memFree=694796/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=0.01 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 575 1519 0 0 0 1 0 0 25 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2588 [startup+0.706924 s] /proc/loadavg: 1.01 1.04 1.01 5/38 29207 /proc/meminfo: memFree=694796/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=0.01 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 575 1519 0 0 0 1 0 0 25 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2588 [startup+1.50703 s] /proc/loadavg: 1.01 1.04 1.01 2/39 29215 /proc/meminfo: memFree=672836/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=0.01 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 575 1519 0 0 0 1 0 0 25 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=3448 CPUtime=0 /proc/29213/stat : 29213 (unclasp) S 29204 29204 19908 34817 19908 4202496 407 0 0 0 0 0 0 0 25 0 1 0 65328303 3530752 272 1283457024 134512640 135121179 4289070288 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29213/statm: 862 272 240 149 0 53 0 [pid=29214] ppid=29204 vsize=2696 CPUtime=0 /proc/29214/stat : 29214 (gringo) S 29204 29204 19908 34817 19908 4202496 408 0 0 0 0 0 0 0 25 0 1 0 65328303 2760704 281 1283457024 134512640 137056543 4290391456 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29214/statm: 674 281 252 622 0 49 0 [pid=29215] ppid=29204 vsize=28112 CPUtime=1.49 /proc/29215/stat : 29215 (cudf2lp) R 29204 29204 19908 34817 19908 4202496 8087 0 0 0 146 3 0 0 25 0 1 0 65328303 28786688 6348 1283457024 134512640 135786343 4293363936 18446744073709551615 134566237 0 0 6 0 0 0 0 17 0 0 0 0 /proc/29215/statm: 7028 6348 128 311 0 6715 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 36844 [startup+3.10729 s] /proc/loadavg: 1.01 1.04 1.01 2/39 29215 /proc/meminfo: memFree=647912/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.46 /proc/29204/stat : 29204 (aspuncud-user-1) R 29203 29204 19908 34817 19908 4202496 576 15489 0 0 0 1 240 5 19 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=7228 CPUtime=0.56 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 1487 0 0 0 55 1 0 0 18 0 1 0 65328303 7401472 1297 1283457024 134512640 135121179 4289070288 18446744073709551615 134975843 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 1807 1297 323 149 0 998 0 [pid=29214] ppid=29204 vsize=0 CPUtime=0.07 /proc/29214/stat : 29214 (gringo) Z 29204 29204 19908 34817 19908 4202508 1156 0 0 0 7 0 0 0 18 0 1 0 65328303 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/29214/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 9816 [startup+6.30791 s] /proc/loadavg: 1.09 1.06 1.02 2/37 29215 /proc/meminfo: memFree=682788/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=18204 CPUtime=3.76 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 4396 0 0 0 373 3 0 0 25 0 1 0 65328303 18640896 4000 1283457024 134512640 135121179 4289070288 18446744073709551615 134836200 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 4551 4000 323 149 0 3742 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 20792 [startup+12.7089 s] /proc/loadavg: 1.08 1.06 1.02 2/37 29216 /proc/meminfo: memFree=666304/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=33052 CPUtime=10.17 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 8260 0 0 0 1014 3 0 0 25 0 1 0 65328303 33845248 7679 1283457024 134512640 135121179 4289070288 18446744073709551615 134839481 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 8263 7679 323 149 0 7454 0 Current children cumulated CPU time (s) 12.7 Current children cumulated vsize (KiB) 35640 [startup+25.5035 s] /proc/loadavg: 1.06 1.05 1.02 2/37 29217 /proc/meminfo: memFree=638776/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=59852 CPUtime=22.94 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 14992 0 0 0 2289 5 0 0 25 0 1 0 65328303 61288448 14411 1283457024 134512640 135121179 4289070288 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 14963 14411 323 149 0 14154 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 62440 [startup+51.1106 s] /proc/loadavg: 1.04 1.05 1.01 2/36 29217 /proc/meminfo: memFree=596632/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=102588 CPUtime=48.54 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 25883 0 0 0 4846 8 0 0 25 0 1 0 65328303 105050112 25025 1283457024 134512640 135121179 4289070288 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 25647 25025 323 149 0 24838 0 Current children cumulated CPU time (s) 51.07 Current children cumulated vsize (KiB) 105176 [startup+102.309 s] /proc/loadavg: 1.02 1.04 1.01 2/35 29217 /proc/meminfo: memFree=542576/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=156248 CPUtime=99.7 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 40296 0 0 0 9959 11 0 0 25 0 1 0 65328303 159997952 38280 1283457024 134512640 135121179 4289070288 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 39062 38280 323 149 0 38253 0 Current children cumulated CPU time (s) 102.23 Current children cumulated vsize (KiB) 158836 [startup+162.306 s] /proc/loadavg: 1.00 1.03 1.00 2/35 29217 /proc/meminfo: memFree=482932/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=216436 CPUtime=159.62 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 55975 0 0 0 15944 18 0 0 25 0 1 0 65328303 221630464 53389 1283457024 134512640 135121179 4289070288 18446744073709551615 134873589 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 54109 53389 323 149 0 53300 0 Current children cumulated CPU time (s) 162.15 Current children cumulated vsize (KiB) 219024 [startup+222.305 s] /proc/loadavg: 1.00 1.02 1.00 2/35 29217 /proc/meminfo: memFree=420064/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=277996 CPUtime=219.58 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 72040 0 0 0 21934 24 0 0 25 0 1 0 65328303 284667904 68811 1283457024 134512640 135121179 4289070288 18446744073709551615 134836023 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 69499 68811 323 149 0 68690 0 Current children cumulated CPU time (s) 222.11 Current children cumulated vsize (KiB) 280584 [startup+282.303 s] /proc/loadavg: 1.00 1.02 1.00 2/35 29217 /proc/meminfo: memFree=355336/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=345324 CPUtime=279.52 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 92689 0 0 0 27916 36 0 0 25 0 1 0 65328303 353611776 85222 1283457024 134512640 135121179 4289070288 18446744073709551615 134836042 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 86331 85222 323 149 0 85522 0 Current children cumulated CPU time (s) 282.05 Current children cumulated vsize (KiB) 347912 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.305 s] /proc/loadavg: 1.00 1.02 1.00 2/35 29217 /proc/meminfo: memFree=345788/1048576 swapFree=0/0 [pid=29204] ppid=29203 vsize=2588 CPUtime=2.53 /proc/29204/stat : 29204 (aspuncud-user-1) S 29203 29204 19908 34817 19908 4202496 576 16645 0 0 0 1 247 5 17 0 1 0 65328302 2650112 297 1283457024 134512640 135304128 4294855136 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29204/statm: 647 297 251 194 0 34 0 [pid=29213] ppid=29204 vsize=353676 CPUtime=287.52 /proc/29213/stat : 29213 (unclasp) R 29204 29204 19908 34817 19908 4202496 95405 0 0 0 28714 38 0 0 25 0 1 0 65328303 362164224 87310 1283457024 134512640 135121179 4289070288 18446744073709551615 134836064 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/29213/statm: 88419 87310 323 149 0 87610 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 356264 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.344 CPU time (s): 290.106 CPU user time (s): 289.626 CPU system time (s): 0.48003 CPU usage (%): 99.9182 Max. virtual memory (cumulated for all children) (KiB): 356264 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.626 system time used= 0.48003 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 115026 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 157 involuntary context switches= 3682 runsolver used 0 second user time and 0 second system time The end