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/rand917.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand917.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand917.cudf.s-e-l-s-s.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.17 1.15 1.06 5/36 15085 /proc/meminfo: memFree=383460/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2584 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 3354752 2646016 279 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/15082/statm: 646 279 234 194 0 33 0 [pid=15083] ppid=15082 vsize=2584 CPUtime=0 /proc/15083/stat : 15083 (aspcud-trendy-1) S 15082 15082 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 3354752 2646016 133 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/15083/statm: 646 133 87 194 0 33 0 [pid=15084] ppid=15083 vsize=2584 CPUtime=0 /proc/15084/stat : 15084 (aspcud-trendy-1) R 15083 15082 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 3354752 2646016 150 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15084/statm: 646 150 104 194 0 33 0 [pid=15085] ppid=15084 vsize=2584 CPUtime=0 /proc/15085/stat : 15085 (aspcud-trendy-1) R 15084 15082 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3354752 2646016 46 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15085/statm: 646 46 0 194 0 33 0 [startup+0.205597 s] /proc/loadavg: 1.17 1.15 1.06 5/36 15085 /proc/meminfo: memFree=383460/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.305522 s] /proc/loadavg: 1.17 1.15 1.06 5/36 15085 /proc/meminfo: memFree=383460/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.405539 s] /proc/loadavg: 1.17 1.15 1.06 5/36 15085 /proc/meminfo: memFree=383460/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.705574 s] /proc/loadavg: 1.17 1.15 1.06 5/36 15085 /proc/meminfo: memFree=383460/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50566 s] /proc/loadavg: 1.17 1.15 1.06 2/37 15096 /proc/meminfo: memFree=357276/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=1924 CPUtime=0 /proc/15094/stat : 15094 (clasp) S 15082 15082 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 3354754 1970176 159 1283457024 134512640 136285277 4288736240 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15094/statm: 481 159 144 433 0 46 0 [pid=15095] ppid=15082 vsize=2584 CPUtime=0 /proc/15095/stat : 15095 (gringo) S 15082 15082 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 3354754 2646016 272 1283457024 134512640 136933539 4287038160 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15095/statm: 646 272 242 592 0 51 0 [pid=15096] ppid=15082 vsize=40664 CPUtime=1.5 /proc/15096/stat : 15096 (cudf2lp) R 15082 15082 1511 34817 1511 4202496 11708 0 0 0 142 8 0 0 25 0 1 0 3354754 41639936 8798 1283457024 134512640 135786343 4292644928 18446744073709551615 135053679 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15096/statm: 10166 8798 126 311 0 9853 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47764 [startup+3.10607 s] /proc/loadavg: 1.17 1.15 1.06 3/37 15096 /proc/meminfo: memFree=325408/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=0 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=17448 CPUtime=0.08 /proc/15094/stat : 15094 (clasp) S 15082 15082 1511 34817 1511 4202496 4808 0 0 0 4 4 0 0 18 0 1 0 3354754 17866752 4017 1283457024 134512640 136285277 4288736240 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15094/statm: 4362 4017 177 433 0 3927 0 [pid=15095] ppid=15082 vsize=22104 CPUtime=0.75 /proc/15095/stat : 15095 (gringo) S 15082 15082 1511 34817 1511 4202496 6903 0 0 0 72 3 0 0 18 0 1 0 3354754 22634496 4630 1283457024 134512640 136933539 4287038160 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15095/statm: 5526 4630 242 592 0 4931 0 [pid=15096] ppid=15082 vsize=17680 CPUtime=2.26 /proc/15096/stat : 15096 (cudf2lp) R 15082 15082 1511 34817 1511 4202496 16201 0 0 0 212 14 0 0 25 0 1 0 3354754 18104320 4243 1283457024 134512640 135786343 4292644928 18446744073709551615 135191367 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15096/statm: 4420 4243 138 311 0 4107 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 59824 [startup+6.30713 s] /proc/loadavg: 1.16 1.15 1.06 2/35 15096 /proc/meminfo: memFree=329052/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=55672 CPUtime=2.03 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 17282 0 0 0 195 8 0 0 20 0 1 0 3354754 57008128 13672 1283457024 134512640 136285277 4288736240 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 13918 13672 234 433 0 13483 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 58264 [startup+12.7089 s] /proc/loadavg: 1.14 1.14 1.06 2/35 15096 /proc/meminfo: memFree=329176/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=55672 CPUtime=8.42 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 17296 0 0 0 834 8 0 0 25 0 1 0 3354754 57008128 13686 1283457024 134512640 136285277 4288736240 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 13918 13686 234 433 0 13483 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 58264 [startup+25.5124 s] /proc/loadavg: 1.11 1.14 1.06 2/35 15096 /proc/meminfo: memFree=295200/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=90276 CPUtime=21.2 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 25932 0 0 0 2110 10 0 0 25 0 1 0 3354754 92442624 22322 1283457024 134512640 136285277 4288736240 18446744073709551615 134723300 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 22569 22322 234 433 0 22134 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 92868 [startup+51.1086 s] /proc/loadavg: 1.07 1.12 1.06 2/35 15096 /proc/meminfo: memFree=237292/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=148172 CPUtime=46.79 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 40382 0 0 0 4663 16 0 0 25 0 1 0 3354754 151728128 36772 1283457024 134512640 136285277 4288736240 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 37043 36772 234 433 0 36608 0 Current children cumulated CPU time (s) 51.05 Current children cumulated vsize (KiB) 150764 [startup+102.313 s] /proc/loadavg: 1.03 1.10 1.05 2/35 15096 /proc/meminfo: memFree=193892/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=199580 CPUtime=97.97 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 53260 0 0 0 9774 23 0 0 25 0 1 0 3354754 204369920 49650 1283457024 134512640 136285277 4288736240 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 49895 49650 234 433 0 49460 0 Current children cumulated CPU time (s) 102.23 Current children cumulated vsize (KiB) 202172 [startup+162.309 s] /proc/loadavg: 1.01 1.08 1.04 2/35 15096 /proc/meminfo: memFree=96056/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=289140 CPUtime=157.91 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 75607 0 0 0 15759 32 0 0 25 0 1 0 3354754 296079360 71997 1283457024 134512640 136285277 4288736240 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 72285 71997 234 433 0 71850 0 Current children cumulated CPU time (s) 162.17 Current children cumulated vsize (KiB) 291732 [startup+222.305 s] /proc/loadavg: 1.00 1.06 1.04 2/37 15099 /proc/meminfo: memFree=41596/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=343484 CPUtime=217.88 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 89153 0 0 0 21751 37 0 0 25 0 1 0 3354754 351727616 85543 1283457024 134512640 136285277 4288736240 18446744073709551615 134955172 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 85871 85543 234 433 0 85436 0 Current children cumulated CPU time (s) 222.14 Current children cumulated vsize (KiB) 346076 [startup+282.312 s] /proc/loadavg: 1.00 1.05 1.03 2/37 15105 /proc/meminfo: memFree=39364/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=345596 CPUtime=277.84 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 89692 0 0 0 27747 37 0 0 25 0 1 0 3354754 353890304 86082 1283457024 134512640 136285277 4288736240 18446744073709551615 134959998 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 86399 86082 234 433 0 85964 0 Current children cumulated CPU time (s) 282.1 Current children cumulated vsize (KiB) 348188 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.305 s] /proc/loadavg: 1.00 1.05 1.03 2/37 15106 /proc/meminfo: memFree=39364/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=345596 CPUtime=285.83 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 89692 0 0 0 28546 37 0 0 25 0 1 0 3354754 353890304 86082 1283457024 134512640 136285277 4288736240 18446744073709551615 134734304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 86399 86082 234 433 0 85964 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 348188 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+290.305 s] /proc/loadavg: 1.00 1.05 1.03 2/37 15106 /proc/meminfo: memFree=39364/1048576 swapFree=0/0 [pid=15082] ppid=15081 vsize=2592 CPUtime=4.26 /proc/15082/stat : 15082 (aspcud-trendy-1) S 15081 15082 1511 34817 1511 4202496 623 38051 0 0 0 0 402 24 18 0 1 0 3354752 2654208 298 1283457024 134512640 135304128 4294134096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15082/statm: 648 298 251 194 0 35 0 [pid=15094] ppid=15082 vsize=345596 CPUtime=285.83 /proc/15094/stat : 15094 (clasp) R 15082 15082 1511 34817 1511 4202496 89692 0 0 0 28546 37 0 0 25 0 1 0 3354754 353890304 86082 1283457024 134512640 136285277 4288736240 18446744073709551615 134734304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15094/statm: 86399 86082 234 433 0 85964 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 348188 Child status: 0 Real time (s): 290.349 CPU time (s): 290.15 CPU user time (s): 289.49 CPU system time (s): 0.660041 CPU usage (%): 99.9314 Max. virtual memory (cumulated for all children) (KiB): 348188 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.49 system time used= 0.660041 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 132120 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= 2930 involuntary context switches= 5794 runsolver used 0 second user time and 0 second system time The end