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/rand494.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand494.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand494.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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.01 1.00 1/40 17193 /proc/meminfo: memFree=773292/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=3024 CPUtime=0 /proc/17193/stat : 17193 (runsolver) D 17192 17193 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 880780446 3096576 93 1283457024 134512640 134586868 4290337904 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/17193/statm: 756 93 62 19 0 54 0 [startup+0.117846 s] /proc/loadavg: 1.00 1.01 1.00 1/40 17193 /proc/meminfo: memFree=773292/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=0 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 624 2216 0 3 0 0 0 0 25 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.20585 s] /proc/loadavg: 1.00 1.01 1.00 1/40 17193 /proc/meminfo: memFree=773292/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=0 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 624 2216 0 3 0 0 0 0 25 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.309862 s] /proc/loadavg: 1.00 1.01 1.00 1/40 17193 /proc/meminfo: memFree=773292/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=0 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 624 2216 0 3 0 0 0 0 25 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.709925 s] /proc/loadavg: 1.00 1.01 1.00 1/40 17193 /proc/meminfo: memFree=773292/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=0 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 624 2216 0 3 0 0 0 0 25 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51013 s] /proc/loadavg: 1.00 1.01 1.00 2/44 17207 /proc/meminfo: memFree=735328/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=0 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 624 2216 0 3 0 0 0 0 25 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=1868 CPUtime=0 /proc/17205/stat : 17205 (clasp) S 17193 17193 4159 34819 4229 4202496 270 0 15 0 0 0 0 0 24 0 1 0 880780451 1912832 152 1283457024 134512640 136223643 4290694672 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/17205/statm: 467 152 138 418 0 47 0 [pid=17206] ppid=17193 vsize=2608 CPUtime=0 /proc/17206/stat : 17206 (gringo) S 17193 17193 4159 34819 4229 4202496 386 0 22 0 0 0 0 0 24 0 1 0 880780451 2670592 276 1283457024 134512640 136959103 4288855744 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/17206/statm: 652 276 247 598 0 51 0 [pid=17207] ppid=17193 vsize=45396 CPUtime=1.29 /proc/17207/stat : 17207 (cudf2lp) R 17193 17193 4159 34819 4229 4202496 14540 0 14 0 125 4 0 0 25 0 1 0 880780451 46485504 11142 1283457024 134512640 135749571 4292243104 18446744073709551615 135031904 0 0 6 0 0 0 0 17 0 0 0 0 /proc/17207/statm: 11349 11142 127 302 0 11045 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 52468 [startup+3.10255 s] /proc/loadavg: 1.00 1.01 1.00 2/44 17207 /proc/meminfo: memFree=701916/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=1.63 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 16762 0 18 0 0 157 6 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=26396 CPUtime=0.16 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 7426 0 18 0 12 4 0 0 18 0 1 0 880780451 27029504 6247 1283457024 134512640 136223643 4290694672 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 6599 6247 174 418 0 6179 0 [pid=17206] ppid=17193 vsize=41808 CPUtime=1.07 /proc/17206/stat : 17206 (gringo) R 17193 17193 4159 34819 4229 4202496 12791 0 22 0 99 8 0 0 18 0 1 0 880780451 42811392 8486 1283457024 134512640 136959103 4288855744 18446744073709551615 134931345 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17206/statm: 10452 8486 256 598 0 9851 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 70800 [startup+6.3147 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17207 /proc/meminfo: memFree=713244/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=58656 CPUtime=2.5 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 17437 0 19 0 242 8 0 0 21 0 1 0 880780451 60063744 13553 1283457024 134512640 136223643 4290694672 18446744073709551615 134870765 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 14664 13553 223 418 0 14244 0 Current children cumulated CPU time (s) 6.07 Current children cumulated vsize (KiB) 61252 [startup+12.7067 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17207 /proc/meminfo: memFree=713988/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=58656 CPUtime=8.89 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 17452 0 19 0 881 8 0 0 25 0 1 0 880780451 60063744 13568 1283457024 134512640 136223643 4290694672 18446744073709551615 134929225 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 14664 13568 225 418 0 14244 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 61252 [startup+25.5091 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17207 /proc/meminfo: memFree=672820/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=100292 CPUtime=21.69 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 27833 0 19 0 2161 8 0 0 25 0 1 0 880780451 102699008 23949 1283457024 134512640 136223643 4290694672 18446744073709551615 134929646 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 25073 23949 225 418 0 24653 0 Current children cumulated CPU time (s) 25.26 Current children cumulated vsize (KiB) 102888 [startup+51.1154 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17207 /proc/meminfo: memFree=663644/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=109412 CPUtime=47.29 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 30126 0 19 0 4719 10 0 0 25 0 1 0 880780451 112037888 26242 1283457024 134512640 136223643 4290694672 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 27353 26242 225 418 0 26933 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 112008 [startup+102.309 s] /proc/loadavg: 1.00 1.00 1.00 2/42 17207 /proc/meminfo: memFree=614168/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=158788 CPUtime=98.42 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 42453 0 19 0 9827 15 0 0 25 0 1 0 880780451 162598912 38569 1283457024 134512640 136223643 4290694672 18446744073709551615 134931129 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 39697 38569 225 418 0 39277 0 Current children cumulated CPU time (s) 101.99 Current children cumulated vsize (KiB) 161384 [startup+162.307 s] /proc/loadavg: 1.00 1.00 1.00 2/42 17207 /proc/meminfo: memFree=572380/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=200608 CPUtime=158.36 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 52870 0 19 0 15814 22 0 0 25 0 1 0 880780451 205422592 48986 1283457024 134512640 136223643 4290694672 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 50152 48986 225 418 0 49732 0 Current children cumulated CPU time (s) 161.93 Current children cumulated vsize (KiB) 203204 [startup+222.308 s] /proc/loadavg: 1.00 1.00 1.00 2/42 17207 /proc/meminfo: memFree=461400/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=312560 CPUtime=218.28 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 80781 0 19 0 21792 36 0 0 25 0 1 0 880780451 320061440 76897 1283457024 134512640 136223643 4290694672 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 78140 76897 225 418 0 77720 0 Current children cumulated CPU time (s) 221.85 Current children cumulated vsize (KiB) 315156 [startup+282.308 s] /proc/loadavg: 1.00 1.00 1.00 2/42 17207 /proc/meminfo: memFree=295736/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=479328 CPUtime=278.22 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 122700 0 19 0 27753 69 0 0 25 0 1 0 880780451 490831872 118523 1283457024 134512640 136223643 4290694672 18446744073709551615 134931073 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 119832 118523 225 418 0 119412 0 Current children cumulated CPU time (s) 281.79 Current children cumulated vsize (KiB) 481924 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.611 s] /proc/loadavg: 1.00 1.00 1.00 2/42 17207 /proc/meminfo: memFree=274904/1048576 swapFree=2080268/2097144 [pid=17193] ppid=17192 vsize=2596 CPUtime=3.57 /proc/17193/stat : 17193 (aspcud-trendy-1) S 17192 17193 4159 34819 4229 4202496 625 35985 0 40 0 0 340 17 18 0 1 0 880780446 2658304 300 1283457024 134512640 135304128 4294138112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17193/statm: 649 300 253 194 0 35 0 [pid=17205] ppid=17193 vsize=498148 CPUtime=286.51 /proc/17205/stat : 17205 (clasp) R 17193 17193 4159 34819 4229 4202496 127391 0 19 0 28579 72 0 0 25 0 1 0 880780451 510103552 123214 1283457024 134512640 136223643 4290694672 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17205/statm: 124537 123214 225 418 0 124117 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 500744 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.678 CPU time (s): 290.142 CPU user time (s): 289.206 CPU system time (s): 0.936058 CPU usage (%): 99.8157 Max. virtual memory (cumulated for all children) (KiB): 500744 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.206 system time used= 0.936058 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 166627 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= 3015 involuntary context switches= 5775 runsolver used 0 second user time and 0.004 second system time The end