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/rand58.cudf.s-e-l.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand58.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand58.cudf.s-e-l.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 5/36 15597 /proc/meminfo: memFree=550088/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2584 CPUtime=0 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 3597285 2646016 279 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/15594/statm: 646 279 234 194 0 33 0 [pid=15595] ppid=15594 vsize=2584 CPUtime=0 /proc/15595/stat : 15595 (aspcud-trendy-1) S 15594 15594 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 3597285 2646016 133 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/15595/statm: 646 133 87 194 0 33 0 [pid=15596] ppid=15595 vsize=2584 CPUtime=0 /proc/15596/stat : 15596 (aspcud-trendy-1) R 15595 15594 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 3597285 2646016 150 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15596/statm: 646 150 104 194 0 33 0 [pid=15597] ppid=15596 vsize=2584 CPUtime=0 /proc/15597/stat : 15597 (aspcud-trendy-1) R 15596 15594 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3597285 2646016 46 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15597/statm: 646 46 0 194 0 33 0 [startup+0.105225 s] /proc/loadavg: 1.00 1.01 1.00 5/36 15597 /proc/meminfo: memFree=550088/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=0.01 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 616 2233 0 0 0 0 1 0 25 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.205249 s] /proc/loadavg: 1.00 1.01 1.00 5/36 15597 /proc/meminfo: memFree=550088/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=0.01 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 616 2233 0 0 0 0 1 0 25 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.305269 s] /proc/loadavg: 1.00 1.01 1.00 5/36 15597 /proc/meminfo: memFree=550088/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=0.01 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 616 2233 0 0 0 0 1 0 25 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.705388 s] /proc/loadavg: 1.00 1.01 1.00 5/36 15597 /proc/meminfo: memFree=550088/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=0.01 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 616 2233 0 0 0 0 1 0 25 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50558 s] /proc/loadavg: 1.00 1.01 1.00 2/37 15608 /proc/meminfo: memFree=518944/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=0.01 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 616 2233 0 0 0 0 1 0 25 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=6500 CPUtime=0.01 /proc/15606/stat : 15606 (clasp) S 15594 15594 1511 34817 1511 4202496 1546 0 0 0 1 0 0 0 18 0 1 0 3597286 6656000 1332 1283457024 134512640 136285277 4291446416 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15606/statm: 1625 1332 177 433 0 1190 0 [pid=15607] ppid=15594 vsize=9012 CPUtime=0.22 /proc/15607/stat : 15607 (gringo) R 15594 15594 1511 34817 1511 4202496 2439 0 0 0 22 0 0 0 18 0 1 0 3597286 9228288 1628 1283457024 134512640 136933539 4292974720 18446744073709551615 134749515 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15607/statm: 2253 1628 242 592 0 1658 0 [pid=15608] ppid=15594 vsize=30568 CPUtime=1.24 /proc/15608/stat : 15608 (cudf2lp) R 15594 15594 1511 34817 1511 4202496 10054 0 0 0 120 4 0 0 25 0 1 0 3597286 31301632 7425 1283457024 134512640 135786343 4294148528 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15608/statm: 7642 7425 137 311 0 7329 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 48672 [startup+3.10606 s] /proc/loadavg: 1.00 1.01 1.00 3/36 15608 /proc/meminfo: memFree=510528/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=35752 CPUtime=0.58 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 10395 0 0 0 51 7 0 0 18 0 1 0 3597286 36610048 8651 1283457024 134512640 136285277 4291446416 18446744073709551615 134899698 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 8938 8651 218 433 0 8503 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 38344 [startup+6.30702 s] /proc/loadavg: 1.00 1.01 1.00 2/35 15608 /proc/meminfo: memFree=516256/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=35208 CPUtime=3.78 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 10427 0 0 0 370 8 0 0 25 0 1 0 3597286 36052992 8567 1283457024 134512640 136285277 4291446416 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 8802 8567 234 433 0 8367 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 37800 [startup+12.7084 s] /proc/loadavg: 1.00 1.01 1.00 2/35 15608 /proc/meminfo: memFree=505352/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=49524 CPUtime=10.18 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 14006 0 0 0 1010 8 0 0 25 0 1 0 3597286 50712576 12146 1283457024 134512640 136285277 4291446416 18446744073709551615 134931346 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 12381 12146 234 433 0 11946 0 Current children cumulated CPU time (s) 12.7 Current children cumulated vsize (KiB) 52116 [startup+25.5113 s] /proc/loadavg: 1.00 1.01 1.00 2/35 15608 /proc/meminfo: memFree=485760/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=67516 CPUtime=22.98 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 18495 0 0 0 2286 12 0 0 25 0 1 0 3597286 69136384 16635 1283457024 134512640 136285277 4291446416 18446744073709551615 134734287 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 16879 16635 234 433 0 16444 0 Current children cumulated CPU time (s) 25.5 Current children cumulated vsize (KiB) 70108 [startup+51.1108 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15608 /proc/meminfo: memFree=470384/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=81712 CPUtime=48.57 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 22037 0 0 0 4845 12 0 0 25 0 1 0 3597286 83673088 20177 1283457024 134512640 136285277 4291446416 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 20428 20177 234 433 0 19993 0 Current children cumulated CPU time (s) 51.09 Current children cumulated vsize (KiB) 84304 [startup+102.313 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15608 /proc/meminfo: memFree=455132/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=96940 CPUtime=99.74 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 25827 0 0 0 9962 12 0 0 25 0 1 0 3597286 99266560 23967 1283457024 134512640 136285277 4291446416 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 24235 23967 234 433 0 23800 0 Current children cumulated CPU time (s) 102.26 Current children cumulated vsize (KiB) 99532 [startup+162.306 s] /proc/loadavg: 1.00 1.00 1.00 2/35 15608 /proc/meminfo: memFree=396232/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=156808 CPUtime=159.69 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 40775 0 0 0 15950 19 0 0 25 0 1 0 3597286 160571392 38915 1283457024 134512640 136285277 4291446416 18446744073709551615 134945951 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 39202 38915 234 433 0 38767 0 Current children cumulated CPU time (s) 162.21 Current children cumulated vsize (KiB) 159400 [startup+222.311 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15613 /proc/meminfo: memFree=379716/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=171972 CPUtime=219.63 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 44577 0 0 0 21942 21 0 0 25 0 1 0 3597286 176099328 42717 1283457024 134512640 136285277 4291446416 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 42993 42717 234 433 0 42558 0 Current children cumulated CPU time (s) 222.15 Current children cumulated vsize (KiB) 174564 [startup+282.304 s] /proc/loadavg: 1.00 1.00 1.00 2/37 15619 /proc/meminfo: memFree=363968/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=187548 CPUtime=279.58 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 48497 0 0 0 27931 27 0 0 25 0 1 0 3597286 192049152 46637 1283457024 134512640 136285277 4291446416 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 46887 46637 234 433 0 46452 0 Current children cumulated CPU time (s) 282.1 Current children cumulated vsize (KiB) 190140 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.207 s] /proc/loadavg: 1.00 1.00 1.00 2/36 15619 /proc/meminfo: memFree=363984/1048576 swapFree=0/0 [pid=15594] ppid=15593 vsize=2592 CPUtime=2.52 /proc/15594/stat : 15594 (aspcud-trendy-1) S 15593 15594 1511 34817 1511 4202496 617 25372 0 0 0 0 242 10 18 0 1 0 3597285 2654208 298 1283457024 134512640 135304128 4291559152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15594/statm: 648 298 251 194 0 35 0 [pid=15606] ppid=15594 vsize=187548 CPUtime=287.48 /proc/15606/stat : 15606 (clasp) R 15594 15594 1511 34817 1511 4202496 48497 0 0 0 28721 27 0 0 25 0 1 0 3597286 192049152 46637 1283457024 134512640 136285277 4291446416 18446744073709551615 134686265 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15606/statm: 46887 46637 234 433 0 46452 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 190140 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.245 CPU time (s): 290.046 CPU user time (s): 289.646 CPU system time (s): 0.400025 CPU usage (%): 99.9313 Max. virtual memory (cumulated for all children) (KiB): 190140 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.646 system time used= 0.400025 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 78152 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= 1250 involuntary context switches= 4348 runsolver used 0 second user time and 0 second system time The end