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/aspcud-1.5/rand408.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand408.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand408.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.03 1.02 1.00 5/39 23914 /proc/meminfo: memFree=653716/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2588 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 62763870 2650112 280 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/23912/statm: 647 280 234 194 0 34 0 [pid=23913] ppid=23912 vsize=2588 CPUtime=0 /proc/23913/stat : 23913 (aspcud-1.5) R 23912 23912 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 62763870 2650112 133 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/23913/statm: 647 133 86 194 0 34 0 [pid=23914] ppid=23913 vsize=2588 CPUtime=0 /proc/23914/stat : 23914 (aspcud-1.5) R 23913 23912 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 62763870 2650112 47 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/23914/statm: 647 47 0 194 0 34 0 [startup+0.118674 s] /proc/loadavg: 1.03 1.02 1.00 5/39 23914 /proc/meminfo: memFree=653716/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.20668 s] /proc/loadavg: 1.03 1.02 1.00 5/39 23914 /proc/meminfo: memFree=653716/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30668 s] /proc/loadavg: 1.03 1.02 1.00 5/39 23914 /proc/meminfo: memFree=653716/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706714 s] /proc/loadavg: 1.03 1.02 1.00 5/39 23914 /proc/meminfo: memFree=653716/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50677 s] /proc/loadavg: 1.03 1.02 1.00 2/41 23923 /proc/meminfo: memFree=620932/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=0 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=1932 CPUtime=0 /proc/23921/stat : 23921 (clasp) S 23912 23912 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 62763871 1978368 160 1283457024 134512640 136285277 4291036736 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/23921/statm: 483 160 144 433 0 48 0 [pid=23922] ppid=23912 vsize=2584 CPUtime=0 /proc/23922/stat : 23922 (gringo) S 23912 23912 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 62763871 2646016 272 1283457024 134512640 136933539 4289289488 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/23922/statm: 646 272 242 592 0 51 0 [pid=23923] ppid=23912 vsize=28108 CPUtime=1.22 /proc/23923/stat : 23923 (cudf2lp) R 23912 23912 19908 34817 19908 4202496 8013 0 0 0 120 2 0 0 25 0 1 0 62763871 28782592 6268 1283457024 134512640 135786343 4293673280 18446744073709551615 134566237 0 0 6 0 0 0 0 17 0 0 0 0 /proc/23923/statm: 7027 6268 128 311 0 6714 0 Current children cumulated CPU time (s) 1.22 Current children cumulated vsize (KiB) 35220 [startup+3.1079 s] /proc/loadavg: 1.03 1.02 1.00 2/41 23923 /proc/meminfo: memFree=586572/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.22 /proc/23912/stat : 23912 (aspcud-1.5) R 23911 23912 19908 34817 19908 4202496 581 15494 0 0 0 0 218 4 19 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=3936 CPUtime=0.42 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 897 0 0 0 42 0 0 0 18 0 1 0 62763871 4030464 764 1283457024 134512640 136285277 4291036736 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 984 764 233 433 0 549 0 [pid=23922] ppid=23912 vsize=0 CPUtime=0.06 /proc/23922/stat : 23922 (gringo) Z 23912 23912 19908 34817 19908 4202508 1008 0 0 0 6 0 0 0 18 0 1 0 62763871 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/23922/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.7 Current children cumulated vsize (KiB) 6532 [startup+6.30844 s] /proc/loadavg: 1.03 1.02 1.00 2/39 23923 /proc/meminfo: memFree=619836/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=5160 CPUtime=3.62 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 1196 0 0 0 362 0 0 0 25 0 1 0 62763871 5283840 1063 1283457024 134512640 136285277 4291036736 18446744073709551615 134966630 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 1290 1063 234 433 0 855 0 Current children cumulated CPU time (s) 5.9 Current children cumulated vsize (KiB) 7756 [startup+12.7101 s] /proc/loadavg: 1.02 1.02 1.00 2/39 23923 /proc/meminfo: memFree=619216/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=5728 CPUtime=10.01 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 1355 0 0 0 1001 0 0 0 25 0 1 0 62763871 5865472 1222 1283457024 134512640 136285277 4291036736 18446744073709551615 134959529 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 1432 1222 234 433 0 997 0 Current children cumulated CPU time (s) 12.29 Current children cumulated vsize (KiB) 8324 [startup+25.5128 s] /proc/loadavg: 1.02 1.02 1.00 2/39 23923 /proc/meminfo: memFree=618720/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=6108 CPUtime=22.8 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 1452 0 0 0 2280 0 0 0 25 0 1 0 62763871 6254592 1317 1283457024 134512640 136285277 4291036736 18446744073709551615 134669984 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 1527 1317 234 433 0 1092 0 Current children cumulated CPU time (s) 25.08 Current children cumulated vsize (KiB) 8704 [startup+51.1078 s] /proc/loadavg: 1.01 1.02 1.00 2/39 23923 /proc/meminfo: memFree=617976/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=6828 CPUtime=48.39 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 1678 0 0 0 4839 0 0 0 25 0 1 0 62763871 6991872 1489 1283457024 134512640 136285277 4291036736 18446744073709551615 134615122 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 1707 1489 234 433 0 1272 0 Current children cumulated CPU time (s) 50.67 Current children cumulated vsize (KiB) 9424 [startup+102.309 s] /proc/loadavg: 1.00 1.01 1.00 2/38 23923 /proc/meminfo: memFree=617240/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=7616 CPUtime=99.57 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 1938 0 0 0 9957 0 0 0 25 0 1 0 62763871 7798784 1680 1283457024 134512640 136285277 4291036736 18446744073709551615 134960059 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 1904 1680 234 433 0 1469 0 Current children cumulated CPU time (s) 101.85 Current children cumulated vsize (KiB) 10212 [startup+162.311 s] /proc/loadavg: 1.00 1.01 1.00 2/38 23923 /proc/meminfo: memFree=616744/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=8076 CPUtime=159.54 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 2303 0 0 0 15954 0 0 0 25 0 1 0 62763871 8269824 1806 1283457024 134512640 136285277 4291036736 18446744073709551615 134930652 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 2019 1806 234 433 0 1584 0 Current children cumulated CPU time (s) 161.82 Current children cumulated vsize (KiB) 10672 [startup+222.302 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23923 /proc/meminfo: memFree=616496/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=8312 CPUtime=219.52 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 2355 0 0 0 21950 2 0 0 25 0 1 0 62763871 8511488 1858 1283457024 134512640 136285277 4291036736 18446744073709551615 134669568 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 2078 1858 234 433 0 1643 0 Current children cumulated CPU time (s) 221.8 Current children cumulated vsize (KiB) 10908 [startup+282.314 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23923 /proc/meminfo: memFree=616372/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=8440 CPUtime=279.44 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 2396 0 0 0 27942 2 0 0 25 0 1 0 62763871 8642560 1899 1283457024 134512640 136285277 4291036736 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 2110 1899 234 433 0 1675 0 Current children cumulated CPU time (s) 281.72 Current children cumulated vsize (KiB) 11036 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.606 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23923 /proc/meminfo: memFree=616372/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=8440 CPUtime=287.74 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 2399 0 0 0 28772 2 0 0 25 0 1 0 62763871 8642560 1902 1283457024 134512640 136285277 4291036736 18446744073709551615 134930755 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 2110 1902 234 433 0 1675 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 11036 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.606 s] /proc/loadavg: 1.00 1.00 1.00 2/38 23923 /proc/meminfo: memFree=616372/1048576 swapFree=0/0 [pid=23912] ppid=23911 vsize=2596 CPUtime=2.28 /proc/23912/stat : 23912 (aspcud-1.5) S 23911 23912 19908 34817 19908 4202496 581 16502 0 0 0 0 224 4 17 0 1 0 62763870 2658304 299 1283457024 134512640 135304128 4289299632 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/23912/statm: 649 299 251 194 0 36 0 [pid=23921] ppid=23912 vsize=8440 CPUtime=287.74 /proc/23921/stat : 23921 (clasp) R 23912 23912 19908 34817 19908 4202496 2399 0 0 0 28772 2 0 0 25 0 1 0 62763871 8642560 1902 1283457024 134512640 136285277 4291036736 18446744073709551615 134930755 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/23921/statm: 2110 1902 234 433 0 1675 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 11036 Child status: 0 Real time (s): 290.626 CPU time (s): 290.058 CPU user time (s): 289.97 CPU system time (s): 0.088005 CPU usage (%): 99.8046 Max. virtual memory (cumulated for all children) (KiB): 57304 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.97 system time used= 0.088005 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23034 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= 190 involuntary context switches= 3710 runsolver used 0 second user time and 0.012 second system time The end