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/rand316.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand316.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand316.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.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.00 1.04 1.01 2/40 14907 /proc/meminfo: memFree=654992/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=3024 CPUtime=0 /proc/14907/stat : 14907 (runsolver) D 14906 14907 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 880214158 3096576 94 1283457024 134512640 134586868 4288484032 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/14907/statm: 756 94 62 19 0 54 0 [startup+0.170573 s] /proc/loadavg: 1.00 1.04 1.01 2/40 14907 /proc/meminfo: memFree=654992/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=0 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.206609 s] /proc/loadavg: 1.00 1.04 1.01 2/40 14907 /proc/meminfo: memFree=654992/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=0 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.306563 s] /proc/loadavg: 1.00 1.04 1.01 2/40 14907 /proc/meminfo: memFree=654992/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=0 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.712422 s] /proc/loadavg: 1.00 1.04 1.01 2/40 14907 /proc/meminfo: memFree=654992/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=0 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.51267 s] /proc/loadavg: 1.00 1.04 1.01 2/44 14921 /proc/meminfo: memFree=617552/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=0 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=1868 CPUtime=0 /proc/14919/stat : 14919 (clasp) D 14907 14907 4159 34819 4229 4202496 275 0 15 0 0 0 0 0 18 0 1 0 880214163 1912832 158 1283457024 134512640 136223643 4289605168 18446744073709551615 134647872 0 0 6 16384 18446744071564332000 0 0 17 0 0 0 0 /proc/14919/statm: 467 158 143 418 0 47 0 [pid=14920] ppid=14907 vsize=2896 CPUtime=0 /proc/14920/stat : 14920 (gringo) R 14907 14907 4159 34819 4229 4202496 436 0 22 0 0 0 0 0 18 0 1 0 880214164 2965504 327 1283457024 134512640 136959103 4288612208 18446744073709551615 136227615 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14920/statm: 724 327 247 598 0 123 0 [pid=14921] ppid=14907 vsize=43448 CPUtime=1.23 /proc/14921/stat : 14921 (cudf2lp) R 14907 14907 4159 34819 4229 4202496 14007 0 14 0 117 6 0 0 25 0 1 0 880214164 44490752 10656 1283457024 134512640 135749571 4288609312 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/14921/statm: 10862 10656 129 302 0 10558 0 Current children cumulated CPU time (s) 1.23 Current children cumulated vsize (KiB) 50812 [startup+3.10927 s] /proc/loadavg: 1.00 1.04 1.01 3/44 14921 /proc/meminfo: memFree=585628/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=1.51 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 16223 3 18 0 0 144 7 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=26660 CPUtime=0.12 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 7492 0 18 0 9 3 0 0 18 0 1 0 880214163 27299840 6314 1283457024 134512640 136223643 4289605168 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 6665 6314 174 418 0 6245 0 [pid=14920] ppid=14907 vsize=43868 CPUtime=1.19 /proc/14920/stat : 14920 (gringo) R 14907 14907 4159 34819 4229 4202496 13141 0 22 0 115 4 0 0 18 0 1 0 880214164 44920832 8837 1283457024 134512640 136959103 4288612208 18446744073709551615 134598797 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14920/statm: 10967 8837 256 598 0 10366 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 73128 [startup+6.31231 s] /proc/loadavg: 1.00 1.04 1.01 2/42 14921 /proc/meminfo: memFree=597760/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=56432 CPUtime=2.54 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 16343 0 19 0 246 8 0 0 21 0 1 0 880214163 57786368 13038 1283457024 134512640 136223643 4289605168 18446744073709551615 134603988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 14108 13038 223 418 0 13688 0 Current children cumulated CPU time (s) 6.01 Current children cumulated vsize (KiB) 59032 [startup+12.7043 s] /proc/loadavg: 1.00 1.04 1.01 2/42 14921 /proc/meminfo: memFree=594164/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=66784 CPUtime=8.93 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 18917 0 19 0 885 8 0 0 25 0 1 0 880214163 68386816 15612 1283457024 134512640 136223643 4289605168 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 16696 15612 225 418 0 16276 0 Current children cumulated CPU time (s) 12.4 Current children cumulated vsize (KiB) 69384 [startup+25.5076 s] /proc/loadavg: 1.00 1.04 1.01 2/42 14921 /proc/meminfo: memFree=570728/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=83980 CPUtime=21.72 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 23237 0 19 0 2163 9 0 0 25 0 1 0 880214163 85995520 19932 1283457024 134512640 136223643 4289605168 18446744073709551615 134711759 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 20995 19932 225 418 0 20575 0 Current children cumulated CPU time (s) 25.19 Current children cumulated vsize (KiB) 86580 [startup+51.1141 s] /proc/loadavg: 1.00 1.04 1.01 2/42 14921 /proc/meminfo: memFree=557832/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=96736 CPUtime=47.29 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 26585 0 19 0 4715 14 0 0 25 0 1 0 880214163 99057664 23113 1283457024 134512640 136223643 4289605168 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 24184 23113 225 418 0 23764 0 Current children cumulated CPU time (s) 50.76 Current children cumulated vsize (KiB) 99336 [startup+102.309 s] /proc/loadavg: 1.00 1.03 1.00 2/42 14921 /proc/meminfo: memFree=430360/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=224020 CPUtime=98.42 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 58380 0 19 0 9812 30 0 0 25 0 1 0 880214163 229396480 54908 1283457024 134512640 136223643 4289605168 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 56005 54908 225 418 0 55585 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 226620 [startup+162.305 s] /proc/loadavg: 1.00 1.02 1.00 2/42 14921 /proc/meminfo: memFree=364516/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=289780 CPUtime=158.39 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 74811 0 19 0 15800 39 0 0 25 0 1 0 880214163 296734720 71339 1283457024 134512640 136223643 4289605168 18446744073709551615 134711893 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 72445 71339 225 418 0 72025 0 Current children cumulated CPU time (s) 161.86 Current children cumulated vsize (KiB) 292380 [startup+222.309 s] /proc/loadavg: 1.00 1.02 1.00 2/42 14921 /proc/meminfo: memFree=245600/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=408764 CPUtime=218.21 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 104620 0 19 0 21772 49 0 0 25 0 1 0 880214163 418574336 101012 1283457024 134512640 136223643 4289605168 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 102191 101012 225 418 0 101771 0 Current children cumulated CPU time (s) 221.68 Current children cumulated vsize (KiB) 411364 [startup+282.308 s] /proc/loadavg: 1.00 1.01 1.00 2/42 14921 /proc/meminfo: memFree=161280/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=492816 CPUtime=278.14 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 125788 0 19 0 27746 68 0 0 25 0 1 0 880214163 504643584 122023 1283457024 134512640 136223643 4289605168 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 123204 122023 225 418 0 122784 0 Current children cumulated CPU time (s) 281.61 Current children cumulated vsize (KiB) 495416 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.711 s] /proc/loadavg: 1.00 1.01 1.00 2/42 14921 /proc/meminfo: memFree=161280/1048576 swapFree=2080252/2097144 [pid=14907] ppid=14906 vsize=2600 CPUtime=3.47 /proc/14907/stat : 14907 (aspcud-trendy-1) S 14906 14907 4159 34819 4229 4202496 623 34999 3 40 0 0 332 15 18 0 1 0 880214158 2662400 300 1283457024 134512640 135304128 4290848240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14907/statm: 650 300 253 194 0 36 0 [pid=14919] ppid=14907 vsize=492816 CPUtime=286.53 /proc/14919/stat : 14919 (clasp) R 14907 14907 4159 34819 4229 4202496 125789 0 19 0 28585 68 0 0 25 0 1 0 880214163 504643584 122024 1283457024 134512640 136223643 4289605168 18446744073709551615 134650872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14919/statm: 123204 122024 225 418 0 122784 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 495416 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.793 CPU time (s): 290.046 CPU user time (s): 289.178 CPU system time (s): 0.868054 CPU usage (%): 99.7432 Max. virtual memory (cumulated for all children) (KiB): 495416 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.178 system time used= 0.868054 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 164021 page faults= 64 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2865 involuntary context switches= 5643 runsolver used 0 second user time and 0 second system time The end