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/201108241238/aspcud-trendy-1.5/rand662.cudf.dudf-random.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-random//rand662.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand662.cudf.dudf-random.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.28 1.28 1.14 5/35 22214 /proc/meminfo: memFree=305756/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2592 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4639995 2654208 280 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/22212/statm: 648 280 234 194 0 35 0 [pid=22213] ppid=22212 vsize=2592 CPUtime=0 /proc/22213/stat : 22213 (aspcud-trendy-1) R 22212 22212 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4639995 2654208 133 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/22213/statm: 648 133 86 194 0 35 0 [pid=22214] ppid=22213 vsize=2592 CPUtime=0 /proc/22214/stat : 22214 (aspcud-trendy-1) R 22213 22212 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4639995 2654208 47 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/22214/statm: 648 47 0 194 0 35 0 [startup+0.155358 s] /proc/loadavg: 1.28 1.28 1.14 5/35 22214 /proc/meminfo: memFree=305756/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 624 2224 0 0 0 0 0 0 25 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.205364 s] /proc/loadavg: 1.28 1.28 1.14 5/35 22214 /proc/meminfo: memFree=305756/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 624 2224 0 0 0 0 0 0 25 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.305412 s] /proc/loadavg: 1.28 1.28 1.14 5/35 22214 /proc/meminfo: memFree=305756/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 624 2224 0 0 0 0 0 0 25 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.705525 s] /proc/loadavg: 1.28 1.28 1.14 5/35 22214 /proc/meminfo: memFree=305756/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 624 2224 0 0 0 0 0 0 25 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50574 s] /proc/loadavg: 1.28 1.28 1.14 2/37 22226 /proc/meminfo: memFree=283772/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=0 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 624 2224 0 0 0 0 0 0 25 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=1928 CPUtime=0 /proc/22224/stat : 22224 (clasp) S 22212 22212 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 4639996 1974272 159 1283457024 134512640 136285277 4289199200 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/22224/statm: 482 159 144 433 0 47 0 [pid=22225] ppid=22212 vsize=2584 CPUtime=0 /proc/22225/stat : 22225 (gringo) S 22212 22212 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 4639996 2646016 272 1283457024 134512640 136933539 4287759232 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/22225/statm: 646 272 242 592 0 51 0 [pid=22226] ppid=22212 vsize=25000 CPUtime=1.49 /proc/22226/stat : 22226 (cudf2lp) R 22212 22212 1511 34817 1511 4202496 7216 0 0 0 144 5 0 0 25 0 1 0 4639996 25600000 5617 1283457024 134512640 135786343 4294920816 18446744073709551615 134566216 0 0 6 0 0 0 0 17 0 0 0 0 /proc/22226/statm: 6250 5617 126 311 0 5937 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 32112 [startup+3.10618 s] /proc/loadavg: 1.28 1.28 1.14 3/37 22226 /proc/meminfo: memFree=265296/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=2.45 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 625 15130 0 0 0 0 236 9 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=15604 CPUtime=0.06 /proc/22224/stat : 22224 (clasp) R 22212 22212 1511 34817 1511 4202496 4296 0 0 0 6 0 0 0 18 0 1 0 4639996 15978496 3505 1283457024 134512640 136285277 4289199200 18446744073709551615 135641886 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22224/statm: 3901 3505 177 433 0 3466 0 [pid=22225] ppid=22212 vsize=23876 CPUtime=0.57 /proc/22225/stat : 22225 (gringo) R 22212 22212 1511 34817 1511 4202496 6725 0 0 0 54 3 0 0 18 0 1 0 4639996 24449024 4677 1283457024 134512640 136933539 4287759232 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22225/statm: 5969 4677 253 592 0 5374 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 42080 Solver just ended. Dumping a history of the last processes samples [startup+3.20622 s] /proc/loadavg: 1.28 1.28 1.14 3/37 22226 /proc/meminfo: memFree=265296/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=2.45 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 625 15130 0 0 0 0 236 9 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=17188 CPUtime=0.08 /proc/22224/stat : 22224 (clasp) R 22212 22212 1511 34817 1511 4202496 4737 0 0 0 8 0 0 0 18 0 1 0 4639996 17600512 3946 1283457024 134512640 136285277 4289199200 18446744073709551615 134782208 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22224/statm: 4297 3946 177 433 0 3862 0 [pid=22225] ppid=22212 vsize=27348 CPUtime=0.66 /proc/22225/stat : 22225 (gringo) R 22212 22212 1511 34817 1511 4202496 7540 0 0 0 63 3 0 0 18 0 1 0 4639996 28004352 5363 1283457024 134512640 136933539 4287759232 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22225/statm: 6837 5363 253 592 0 6242 0 Current children cumulated CPU time (s) 3.19 Current children cumulated vsize (KiB) 47136 [startup+4.80662 s] /proc/loadavg: 1.26 1.28 1.14 2/35 22226 /proc/meminfo: memFree=267948/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=3.72 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 625 29156 0 0 0 0 357 15 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=38676 CPUtime=1.08 /proc/22224/stat : 22224 (clasp) R 22212 22212 1511 34817 1511 4202496 11558 0 0 0 106 2 0 0 18 0 1 0 4639996 39604224 9408 1283457024 134512640 136285277 4289199200 18446744073709551615 134686792 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22224/statm: 9669 9408 234 433 0 9234 0 Current children cumulated CPU time (s) 4.8 Current children cumulated vsize (KiB) 41276 [startup+5.60684 s] /proc/loadavg: 1.26 1.28 1.14 2/35 22226 /proc/meminfo: memFree=268444/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=3.72 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 625 29156 0 0 0 0 357 15 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=38676 CPUtime=1.88 /proc/22224/stat : 22224 (clasp) R 22212 22212 1511 34817 1511 4202496 11558 0 0 0 185 3 0 0 20 0 1 0 4639996 39604224 9408 1283457024 134512640 136285277 4289199200 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22224/statm: 9669 9408 234 433 0 9234 0 Current children cumulated CPU time (s) 5.6 Current children cumulated vsize (KiB) 41276 [startup+5.8069 s] /proc/loadavg: 1.26 1.28 1.14 2/35 22226 /proc/meminfo: memFree=268444/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=3.72 /proc/22212/stat : 22212 (aspcud-trendy-1) S 22211 22212 1511 34817 1511 4202496 625 29156 0 0 0 0 357 15 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 [pid=22224] ppid=22212 vsize=38676 CPUtime=2.08 /proc/22224/stat : 22224 (clasp) R 22212 22212 1511 34817 1511 4202496 11558 0 0 0 205 3 0 0 20 0 1 0 4639996 39604224 9408 1283457024 134512640 136285277 4289199200 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22224/statm: 9669 9408 234 433 0 9234 0 Current children cumulated CPU time (s) 5.8 Current children cumulated vsize (KiB) 41276 [startup+5.90691 s] /proc/loadavg: 1.26 1.28 1.14 2/35 22226 /proc/meminfo: memFree=268444/1048576 swapFree=0/0 [pid=22212] ppid=22211 vsize=2600 CPUtime=5.89 /proc/22212/stat : 22212 (aspcud-trendy-1) R 22211 22212 1511 34817 1511 4202496 626 40723 0 0 0 0 570 19 18 0 1 0 4639995 2662400 299 1283457024 134512640 135304128 4290131344 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0 /proc/22212/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 5.89 Current children cumulated vsize (KiB) 2600 Child status: 0 Real time (s): 5.93274 CPU time (s): 5.92837 CPU user time (s): 5.72436 CPU system time (s): 0.204012 CPU usage (%): 99.9263 Max. virtual memory (cumulated for all children) (KiB): 84140 getrusage(RUSAGE_CHILDREN,...) data: user time used= 5.72436 system time used= 0.204012 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45318 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= 1586 involuntary context switches= 1205 runsolver used 0 second user time and 0 second system time The end