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/rand180.sarge-etch.cudf.sarge-etch.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch/rand180.sarge-etch.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand180.sarge-etch.cudf.sarge-etch.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.14 1.15 1.06 2/41 12792 /proc/meminfo: memFree=933812/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=3028 CPUtime=0 /proc/12792/stat : 12792 (runsolver) D 12791 12792 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 879593865 3100672 94 1283457024 134512640 134586868 4289823840 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/12792/statm: 757 94 62 19 0 55 0 [startup+0.177566 s] /proc/loadavg: 1.14 1.15 1.06 2/41 12792 /proc/meminfo: memFree=933812/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=0 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 2210 0 3 0 0 0 0 25 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205485 s] /proc/loadavg: 1.14 1.15 1.06 2/41 12792 /proc/meminfo: memFree=933812/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=0 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 2210 0 3 0 0 0 0 25 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306764 s] /proc/loadavg: 1.14 1.15 1.06 2/41 12792 /proc/meminfo: memFree=933812/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=0 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 2210 0 3 0 0 0 0 25 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706893 s] /proc/loadavg: 1.14 1.15 1.06 2/41 12792 /proc/meminfo: memFree=933812/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=0 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 2210 0 3 0 0 0 0 25 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50563 s] /proc/loadavg: 1.12 1.15 1.06 2/44 12806 /proc/meminfo: memFree=910836/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=17260 CPUtime=0.13 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 4511 0 19 0 11 2 0 0 18 0 1 0 879593868 17674240 4012 1283457024 134512640 136223643 4289156768 18446744073709551615 135028791 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 4315 4012 183 418 0 3895 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 19856 [startup+3.10999 s] /proc/loadavg: 1.12 1.15 1.06 2/43 12806 /proc/meminfo: memFree=910172/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=23284 CPUtime=1.73 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 6256 0 19 0 171 2 0 0 20 0 1 0 879593868 23842816 5358 1283457024 134512640 136223643 4289156768 18446744073709551615 134940530 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 5821 5358 225 418 0 5401 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 25880 [startup+6.31071 s] /proc/loadavg: 1.12 1.15 1.06 2/43 12806 /proc/meminfo: memFree=899516/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=32020 CPUtime=4.92 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 8434 0 19 0 490 2 0 0 25 0 1 0 879593868 32788480 7536 1283457024 134512640 136223643 4289156768 18446744073709551615 134928897 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 8005 7536 225 418 0 7585 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 34616 [startup+12.7121 s] /proc/loadavg: 1.10 1.14 1.06 2/42 12806 /proc/meminfo: memFree=889116/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=45352 CPUtime=11.33 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 11771 0 19 0 1131 2 0 0 25 0 1 0 879593868 46440448 10873 1283457024 134512640 136223643 4289156768 18446744073709551615 134940571 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 11338 10873 225 418 0 10918 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 47948 [startup+25.5053 s] /proc/loadavg: 1.09 1.14 1.06 2/42 12806 /proc/meminfo: memFree=838648/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=92524 CPUtime=24.1 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 23539 0 19 0 2402 8 0 0 25 0 1 0 879593868 94744576 22641 1283457024 134512640 136223643 4289156768 18446744073709551615 134931019 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 23131 22641 225 418 0 22711 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 95120 [startup+51.111 s] /proc/loadavg: 1.06 1.13 1.05 2/42 12806 /proc/meminfo: memFree=799092/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=131832 CPUtime=49.69 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 33370 0 19 0 4952 17 0 0 25 0 1 0 879593868 134995968 32472 1283457024 134512640 136223643 4289156768 18446744073709551615 134711220 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 32958 32472 225 418 0 32538 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 134428 [startup+102.307 s] /proc/loadavg: 1.13 1.13 1.06 2/43 12888 /proc/meminfo: memFree=773932/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=134868 CPUtime=100.1 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 34129 0 19 0 9993 17 0 0 25 0 1 0 879593868 138104832 33231 1283457024 134512640 136223643 4289156768 18446744073709551615 134929008 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 33717 33231 225 418 0 33297 0 Current children cumulated CPU time (s) 101.23 Current children cumulated vsize (KiB) 137464 [startup+162.313 s] /proc/loadavg: 1.05 1.11 1.05 2/42 12888 /proc/meminfo: memFree=773320/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=135484 CPUtime=160.04 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 34760 0 19 0 15985 19 0 0 25 0 1 0 879593868 138735616 33394 1283457024 134512640 136223643 4289156768 18446744073709551615 134630032 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 33871 33394 225 418 0 33451 0 Current children cumulated CPU time (s) 161.17 Current children cumulated vsize (KiB) 138080 [startup+222.31 s] /proc/loadavg: 1.02 1.08 1.05 3/42 12888 /proc/meminfo: memFree=772452/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=136436 CPUtime=219.95 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 35190 0 19 0 21975 20 0 0 25 0 1 0 879593868 139710464 33607 1283457024 134512640 136223643 4289156768 18446744073709551615 134906376 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 34109 33607 225 418 0 33689 0 Current children cumulated CPU time (s) 221.08 Current children cumulated vsize (KiB) 139032 [startup+282.306 s] /proc/loadavg: 1.00 1.07 1.04 2/42 12888 /proc/meminfo: memFree=772700/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=136928 CPUtime=279.88 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 35932 0 19 0 27968 20 0 0 25 0 1 0 879593868 140214272 33753 1283457024 134512640 136223643 4289156768 18446744073709551615 134934962 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 34232 33753 225 418 0 33812 0 Current children cumulated CPU time (s) 281.01 Current children cumulated vsize (KiB) 139524 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+291.307 s] /proc/loadavg: 1.00 1.06 1.04 2/42 12888 /proc/meminfo: memFree=771832/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2596 CPUtime=1.13 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 621 14664 0 40 0 0 109 4 15 0 1 0 879593865 2658304 300 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 649 300 253 194 0 35 0 [pid=12804] ppid=12792 vsize=136928 CPUtime=288.87 /proc/12804/stat : 12804 (clasp) R 12792 12792 4159 34819 4229 4202496 35932 0 19 0 28867 20 0 0 25 0 1 0 879593868 140214272 33753 1283457024 134512640 136223643 4289156768 18446744073709551615 134631204 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/12804/statm: 34232 33753 225 418 0 33812 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 139524 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+291.908 s] /proc/loadavg: 1.00 1.06 1.04 1/43 12890 /proc/meminfo: memFree=905612/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2600 CPUtime=290.03 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 650 50596 0 59 0 0 28977 26 15 0 1 0 879593865 2662400 308 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 650 308 260 194 0 36 0 [pid=12890] ppid=12792 vsize=52 CPUtime=0 /proc/12890/stat : 12890 (touch) D 12792 12792 4159 34819 4229 4194304 62 0 0 0 0 0 0 0 18 0 1 0 879622997 53248 1 1283457024 0 0 4290065280 18446744073709551615 4294960130 0 0 16898 0 18446744071564332000 0 0 17 0 0 0 0 /proc/12890/statm: 13 1 0 0 0 1 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 2652 [startup+292.308 s] /proc/loadavg: 1.00 1.06 1.04 1/43 12890 /proc/meminfo: memFree=905612/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2600 CPUtime=290.03 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 650 50596 0 59 0 0 28977 26 15 0 1 0 879593865 2662400 308 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 650 308 260 194 0 36 0 [pid=12890] ppid=12792 vsize=52 CPUtime=0 /proc/12890/stat : 12890 (touch) D 12792 12792 4159 34819 4229 4194304 62 0 0 0 0 0 0 0 18 0 1 0 879622997 53248 1 1283457024 0 0 4290065280 18446744073709551615 4294960130 0 0 16898 0 18446744071564332000 0 0 17 0 0 0 0 /proc/12890/statm: 13 1 0 0 0 1 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 2652 [startup+292.508 s] /proc/loadavg: 1.00 1.06 1.04 1/43 12890 /proc/meminfo: memFree=905612/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2600 CPUtime=290.03 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 650 50596 0 59 0 0 28977 26 15 0 1 0 879593865 2662400 308 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 650 308 260 194 0 36 0 [pid=12890] ppid=12792 vsize=52 CPUtime=0 /proc/12890/stat : 12890 (touch) D 12792 12792 4159 34819 4229 4194304 62 0 0 0 0 0 0 0 18 0 1 0 879622997 53248 1 1283457024 0 0 4290065280 18446744073709551615 4294960130 0 0 16898 0 18446744071564332000 0 0 17 0 0 0 0 /proc/12890/statm: 13 1 0 0 0 1 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 2652 [startup+292.608 s] /proc/loadavg: 1.00 1.06 1.04 1/43 12890 /proc/meminfo: memFree=905620/1048576 swapFree=2076380/2097144 [pid=12792] ppid=12791 vsize=2600 CPUtime=290.03 /proc/12792/stat : 12792 (aspcud-trendy-1) S 12791 12792 4159 34819 4229 4202496 650 50596 0 59 0 0 28977 26 15 0 1 0 879593865 2662400 308 1283457024 134512640 135304128 4289266848 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/12792/statm: 650 308 260 194 0 36 0 [pid=12890] ppid=12792 vsize=52 CPUtime=0 /proc/12890/stat : 12890 (touch) D 12792 12792 4159 34819 4229 4194304 62 0 0 0 0 0 0 0 18 0 1 0 879622997 53248 1 1283457024 0 0 4290065280 18446744073709551615 4294960130 0 0 16898 0 18446744071564332000 0 0 17 0 0 0 0 /proc/12890/statm: 13 1 0 0 0 1 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 2652 Child status: 0 Real time (s): 292.669 CPU time (s): 290.042 CPU user time (s): 289.77 CPU system time (s): 0.272017 CPU usage (%): 99.1026 Max. virtual memory (cumulated for all children) (KiB): 139556 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.77 system time used= 0.272017 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 53831 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= 1221 involuntary context switches= 5200 runsolver used 0 second user time and 0.004 second system time The end