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/201012081719/cudf2pbo4trendy-1.0/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand165.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand165.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: 0.84 0.93 0.90 5/39 9824 /proc/meminfo: memFree=98724/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=2448 CPUtime=0.02 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 434 0 0 0 2 0 0 0 25 0 1 0 892615421 2506752 326 1283457024 134512640 136125367 4288068560 18446744073709551615 134717989 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 612 326 141 394 0 216 0 [startup+0.18498 s] /proc/loadavg: 0.84 0.93 0.90 5/39 9824 /proc/meminfo: memFree=98724/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=9644 CPUtime=0.19 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 2223 0 0 0 19 0 0 0 25 0 1 0 892615421 9875456 2115 1283457024 134512640 136125367 4288068560 18446744073709551615 134718131 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 2411 2115 142 394 0 2015 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 12216 [startup+0.205006 s] /proc/loadavg: 0.84 0.93 0.90 5/39 9824 /proc/meminfo: memFree=98724/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=10256 CPUtime=0.21 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 2388 0 0 0 21 0 0 0 25 0 1 0 892615421 10502144 2280 1283457024 134512640 136125367 4288068560 18446744073709551615 134718168 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 2564 2280 142 394 0 2168 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 12828 [startup+0.305028 s] /proc/loadavg: 0.84 0.93 0.90 5/39 9824 /proc/meminfo: memFree=98724/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=13884 CPUtime=0.31 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 3267 0 0 0 30 1 0 0 25 0 1 0 892615421 14217216 3159 1283457024 134512640 136125367 4288068560 18446744073709551615 134717918 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 3471 3159 143 394 0 3075 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 16456 [startup+0.705128 s] /proc/loadavg: 0.84 0.93 0.90 5/39 9824 /proc/meminfo: memFree=98724/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=25960 CPUtime=0.71 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 6291 0 0 0 69 2 0 0 25 0 1 0 892615421 26583040 6183 1283457024 134512640 136125367 4288068560 18446744073709551615 135691914 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 6490 6183 143 394 0 6094 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 28532 [startup+1.50533 s] /proc/loadavg: 0.84 0.93 0.90 2/40 9825 /proc/meminfo: memFree=64780/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=0 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892615421 2633728 279 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 279 238 194 0 29 0 [pid=9824] ppid=9823 vsize=51724 CPUtime=1.5 /proc/9824/stat : 9824 (cudf_msu32) R 9823 9823 9023 34817 9081 4202496 13115 0 0 0 139 11 0 0 25 0 1 0 892615421 52965376 12666 1283457024 134512640 136125367 4288068560 18446744073709551615 134623647 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9824/statm: 12931 12666 160 394 0 12535 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 54296 [startup+3.10562 s] /proc/loadavg: 0.84 0.93 0.90 2/40 9825 /proc/meminfo: memFree=39980/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 2.32 Current children cumulated vsize (KiB) 2572 heavy processes: [startup+6.3062 s] /proc/loadavg: 0.85 0.93 0.90 2/40 9826 /proc/meminfo: memFree=68748/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=27920 CPUtime=3.97 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 7358 0 0 0 294 103 0 0 25 0 1 0 892615654 28590080 6524 1283457024 134512640 135887319 4292978816 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 6980 6524 138 336 0 6642 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 30492 [startup+12.7076 s] /proc/loadavg: 0.87 0.94 0.90 2/40 9826 /proc/meminfo: memFree=59200/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=37592 CPUtime=10.34 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 11261 0 0 0 750 284 0 0 25 0 1 0 892615654 38494208 8953 1283457024 134512640 135887319 4292978816 18446744073709551615 135339990 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 9398 8953 144 336 0 9060 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 40164 [startup+25.5107 s] /proc/loadavg: 0.89 0.94 0.90 2/40 9826 /proc/meminfo: memFree=36756/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=59640 CPUtime=23.06 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 20147 0 0 0 1874 432 0 0 25 0 1 0 892615654 61071360 14504 1283457024 134512640 135887319 4292978816 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 14910 14504 144 336 0 14572 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 62212 [startup+51.1049 s] /proc/loadavg: 0.93 0.94 0.90 2/40 9826 /proc/meminfo: memFree=35640/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=60696 CPUtime=48.66 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 20424 0 0 0 4433 433 0 0 25 0 1 0 892615654 62152704 14779 1283457024 134512640 135887319 4292978816 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 15174 14779 144 336 0 14836 0 Current children cumulated CPU time (s) 50.98 Current children cumulated vsize (KiB) 63268 [startup+102.307 s] /proc/loadavg: 0.97 0.95 0.91 2/40 9826 /proc/meminfo: memFree=33904/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=62412 CPUtime=99.8 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 20852 0 0 0 9546 434 0 0 25 0 1 0 892615654 63909888 15205 1283457024 134512640 135887319 4292978816 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 15603 15205 144 336 0 15265 0 Current children cumulated CPU time (s) 102.12 Current children cumulated vsize (KiB) 64984 [startup+162.309 s] /proc/loadavg: 0.99 0.95 0.91 2/40 9826 /proc/meminfo: memFree=30928/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=65316 CPUtime=159.8 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 21582 0 0 0 15545 435 0 0 25 0 1 0 892615654 66883584 15927 1283457024 134512640 135887319 4292978816 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 16329 15927 144 336 0 15991 0 Current children cumulated CPU time (s) 162.12 Current children cumulated vsize (KiB) 67888 [startup+222.303 s] /proc/loadavg: 0.99 0.96 0.91 2/40 9826 /proc/meminfo: memFree=27704/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=68356 CPUtime=219.72 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 22357 0 0 0 21533 439 0 0 25 0 1 0 892615654 69996544 16693 1283457024 134512640 135887319 4292978816 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 17089 16693 144 336 0 16751 0 Current children cumulated CPU time (s) 222.04 Current children cumulated vsize (KiB) 70928 [startup+282.307 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9826 /proc/meminfo: memFree=25100/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=71000 CPUtime=279.7 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 23012 0 0 0 27528 442 0 0 25 0 1 0 892615654 72704000 17333 1283457024 134512640 135887319 4292978816 18446744073709551615 134603647 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 17750 17333 144 336 0 17412 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 73572 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.309 s] /proc/loadavg: 0.99 0.97 0.91 2/40 9826 /proc/meminfo: memFree=24852/1048576 swapFree=2095372/2097144 [pid=9823] ppid=9822 vsize=2572 CPUtime=2.32 /proc/9823/stat : 9823 (cudf2pbo4trendy) S 9822 9823 9023 34817 9081 4202496 402 14291 0 0 0 0 178 54 20 0 1 0 892615421 2633728 282 1283457024 134512640 135304128 4292372320 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9823/statm: 643 282 241 194 0 29 0 [pid=9826] ppid=9823 vsize=71264 CPUtime=287.7 /proc/9826/stat : 9826 (bmo-pblex32) R 9823 9823 9023 34817 9081 4202496 23083 0 0 0 28328 442 0 0 25 0 1 0 892615654 72974336 17404 1283457024 134512640 135887319 4292978816 18446744073709551615 134525046 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9826/statm: 17816 17404 144 336 0 17478 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 73836 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.414 CPU time (s): 290.138 CPU user time (s): 285.142 CPU system time (s): 4.99631 CPU usage (%): 99.9048 Max. virtual memory (cumulated for all children) (KiB): 73836 getrusage(RUSAGE_CHILDREN,...) data: user time used= 285.142 system time used= 4.99631 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 39995 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= 19 involuntary context switches= 8089 runsolver used 0 second user time and 0 second system time The end