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/201012070034/aspcud-trendy-1.3/randaafcce.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//randaafcce.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/randaafcce.cudf.impossible.result 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.09 1.10 1.07 2/44 1753 /proc/meminfo: memFree=701672/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=3024 CPUtime=0 /proc/1753/stat : 1753 (runsolver) D 1752 1753 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 884879603 3096576 94 1283457024 134512640 134586868 4289492000 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/1753/statm: 756 94 62 19 0 54 0 [startup+0.164908 s] /proc/loadavg: 1.09 1.10 1.07 2/44 1753 /proc/meminfo: memFree=701672/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.208814 s] /proc/loadavg: 1.09 1.10 1.07 2/44 1753 /proc/meminfo: memFree=701672/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.308838 s] /proc/loadavg: 1.09 1.10 1.07 2/44 1753 /proc/meminfo: memFree=701672/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.70891 s] /proc/loadavg: 1.09 1.10 1.07 2/44 1753 /proc/meminfo: memFree=701672/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50907 s] /proc/loadavg: 1.09 1.10 1.07 2/48 1767 /proc/meminfo: memFree=663236/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=1864 CPUtime=0 /proc/1765/stat : 1765 (clasp) S 1753 1753 4159 34819 4229 4202496 268 0 15 0 0 0 0 0 24 0 1 0 884879607 1908736 152 1283457024 134512640 136223643 4289096672 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1765/statm: 466 152 138 418 0 46 0 [pid=1766] ppid=1753 vsize=2604 CPUtime=0 /proc/1766/stat : 1766 (gringo) S 1753 1753 4159 34819 4229 4202496 384 0 22 0 0 0 0 0 24 0 1 0 884879608 2666496 276 1283457024 134512640 136959103 4290932592 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1766/statm: 651 276 247 598 0 50 0 [pid=1767] ppid=1753 vsize=53644 CPUtime=1.33 /proc/1767/stat : 1767 (cudf2lp) R 1753 1753 4159 34819 4229 4202496 14737 0 14 0 129 4 0 0 25 0 1 0 884879608 54931456 12599 1283457024 134512640 135749571 4289095328 18446744073709551615 135198627 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1767/statm: 13411 12599 127 302 0 13107 0 Current children cumulated CPU time (s) 1.33 Current children cumulated vsize (KiB) 60708 [startup+3.10954 s] /proc/loadavg: 1.24 1.13 1.08 4/48 1767 /proc/meminfo: memFree=626476/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=0 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 2212 0 3 0 0 0 0 25 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=19252 CPUtime=0.06 /proc/1765/stat : 1765 (clasp) S 1753 1753 4159 34819 4229 4202496 5280 0 18 0 6 0 0 0 18 0 1 0 884879607 19714048 4509 1283457024 134512640 136223643 4289096672 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1765/statm: 4813 4509 174 418 0 4393 0 [pid=1766] ppid=1753 vsize=28716 CPUtime=0.92 /proc/1766/stat : 1766 (gringo) R 1753 1753 4159 34819 4229 4202496 8786 0 22 0 88 4 0 0 18 0 1 0 884879608 29405184 5096 1283457024 134512640 136959103 4290932592 18446744073709551615 134587483 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1766/statm: 7179 5096 247 598 0 6578 0 [pid=1767] ppid=1753 vsize=62348 CPUtime=1.92 /proc/1767/stat : 1767 (cudf2lp) R 1753 1753 4159 34819 4229 4202496 18987 0 14 0 188 4 0 0 25 0 1 0 884879608 63844352 15187 1283457024 134512640 135749571 4289095328 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1767/statm: 15587 15187 129 302 0 15283 0 Current children cumulated CPU time (s) 2.9 Current children cumulated vsize (KiB) 112912 [startup+6.31359 s] /proc/loadavg: 1.24 1.13 1.08 2/46 1767 /proc/meminfo: memFree=635996/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=69784 CPUtime=1.49 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 20226 0 19 0 145 4 0 0 19 0 1 0 884879607 71458816 16112 1283457024 134512640 136223643 4289096672 18446744073709551615 134909476 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 17446 16112 217 418 0 17026 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 72380 [startup+12.7153 s] /proc/loadavg: 1.20 1.13 1.08 2/46 1767 /proc/meminfo: memFree=633268/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=68568 CPUtime=7.89 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 20260 0 19 0 785 4 0 0 25 0 1 0 884879607 70213632 15888 1283457024 134512640 136223643 4289096672 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 17142 15888 225 418 0 16722 0 Current children cumulated CPU time (s) 12.49 Current children cumulated vsize (KiB) 71164 [startup+25.5084 s] /proc/loadavg: 1.17 1.12 1.08 2/46 1767 /proc/meminfo: memFree=605616/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=96776 CPUtime=20.69 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 27263 0 19 0 2062 7 0 0 25 0 1 0 884879607 99098624 22891 1283457024 134512640 136223643 4289096672 18446744073709551615 134664690 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 24194 22891 225 418 0 23774 0 Current children cumulated CPU time (s) 25.29 Current children cumulated vsize (KiB) 99372 [startup+51.1079 s] /proc/loadavg: 1.11 1.11 1.07 2/46 1767 /proc/meminfo: memFree=592472/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=109752 CPUtime=46.25 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 30521 0 19 0 4617 8 0 0 25 0 1 0 884879607 112386048 26149 1283457024 134512640 136223643 4289096672 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 27438 26149 225 418 0 27018 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 112348 [startup+102.308 s] /proc/loadavg: 1.04 1.09 1.07 2/46 1767 /proc/meminfo: memFree=565316/1048576 swapFree=2077608/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=136824 CPUtime=97.44 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 37265 0 19 0 9732 12 0 0 25 0 1 0 884879607 140107776 32893 1283457024 134512640 136223643 4289096672 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 34206 32893 225 418 0 33786 0 Current children cumulated CPU time (s) 102.04 Current children cumulated vsize (KiB) 139420 [startup+162.306 s] /proc/loadavg: 1.02 1.07 1.06 2/43 1768 /proc/meminfo: memFree=495112/1048576 swapFree=2080268/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=207304 CPUtime=157.34 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 54910 0 19 0 15713 21 0 0 25 0 1 0 884879607 212279296 50433 1283457024 134512640 136223643 4289096672 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 51826 50433 225 418 0 51406 0 Current children cumulated CPU time (s) 161.94 Current children cumulated vsize (KiB) 209900 [startup+222.314 s] /proc/loadavg: 1.00 1.06 1.06 2/42 1768 /proc/meminfo: memFree=431888/1048576 swapFree=2080268/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=268876 CPUtime=217.33 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 70407 0 19 0 21692 41 0 0 25 0 1 0 884879607 275329024 65794 1283457024 134512640 136223643 4289096672 18446744073709551615 134931115 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 67219 65794 225 418 0 66799 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 271472 [startup+282.306 s] /proc/loadavg: 1.00 1.05 1.05 2/42 1768 /proc/meminfo: memFree=389480/1048576 swapFree=2080268/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=312428 CPUtime=277.27 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 81431 0 19 0 27673 54 0 0 25 0 1 0 884879607 319926272 76661 1283457024 134512640 136223643 4289096672 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 78107 76661 225 418 0 77687 0 Current children cumulated CPU time (s) 281.87 Current children cumulated vsize (KiB) 315024 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.508 s] /proc/loadavg: 1.00 1.04 1.05 2/42 1768 /proc/meminfo: memFree=374476/1048576 swapFree=2080268/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=326120 CPUtime=285.46 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 84877 0 19 0 28489 57 0 0 25 0 1 0 884879607 333946880 80107 1283457024 134512640 136223643 4289096672 18446744073709551615 134611138 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 81530 80107 225 418 0 81110 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 328716 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.508 s] /proc/loadavg: 1.00 1.04 1.05 2/42 1768 /proc/meminfo: memFree=374476/1048576 swapFree=2080268/2097144 [pid=1753] ppid=1752 vsize=2596 CPUtime=4.6 /proc/1753/stat : 1753 (aspcud-trendy-1) S 1752 1753 4159 34819 4229 4202496 620 44580 0 40 0 0 438 22 18 0 1 0 884879603 2658304 299 1283457024 134512640 135304128 4287753024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1753/statm: 649 299 253 194 0 35 0 [pid=1765] ppid=1753 vsize=326120 CPUtime=285.46 /proc/1765/stat : 1765 (clasp) R 1753 1753 4159 34819 4229 4202496 84877 0 19 0 28489 57 0 0 25 0 1 0 884879607 333946880 80107 1283457024 134512640 136223643 4289096672 18446744073709551615 134611138 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1765/statm: 81530 80107 225 418 0 81110 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 328716 Child status: 0 Real time (s): 290.56 CPU time (s): 290.11 CPU user time (s): 289.278 CPU system time (s): 0.832052 CPU usage (%): 99.8453 Max. virtual memory (cumulated for all children) (KiB): 328716 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.278 system time used= 0.832052 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 132698 page faults= 60 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 4052 involuntary context switches= 6821 runsolver used 0 second user time and 0 second system time The end