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/201109011757/aspcud-1.5/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 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.07 1.01 5/35 30620 /proc/meminfo: memFree=511868/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2588 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 373 0 0 0 0 0 0 0 20 0 1 0 72763829 2650112 280 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/30618/statm: 647 280 234 194 0 34 0 [pid=30619] ppid=30618 vsize=2588 CPUtime=0 /proc/30619/stat : 30619 (aspcud-1.5) R 30618 30618 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 72763829 2650112 133 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30619/statm: 647 133 86 194 0 34 0 [pid=30620] ppid=30619 vsize=2588 CPUtime=0 /proc/30620/stat : 30620 (aspcud-1.5) R 30619 30618 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72763829 2650112 47 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30620/statm: 647 47 0 194 0 34 0 [startup+0.150924 s] /proc/loadavg: 1.17 1.07 1.01 5/35 30620 /proc/meminfo: memFree=511868/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206926 s] /proc/loadavg: 1.17 1.07 1.01 5/35 30620 /proc/meminfo: memFree=511868/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306947 s] /proc/loadavg: 1.17 1.07 1.01 5/35 30620 /proc/meminfo: memFree=511868/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707677 s] /proc/loadavg: 1.17 1.07 1.01 5/35 30620 /proc/meminfo: memFree=511868/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50823 s] /proc/loadavg: 1.17 1.07 1.01 2/37 30629 /proc/meminfo: memFree=475880/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=0 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=1928 CPUtime=0 /proc/30627/stat : 30627 (clasp) S 30618 30618 22717 34817 22717 4202496 293 0 0 0 0 0 0 0 25 0 1 0 72763830 1974272 160 1283457024 134512640 136285277 4288254864 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/30627/statm: 482 160 144 433 0 47 0 [pid=30628] ppid=30618 vsize=2588 CPUtime=0 /proc/30628/stat : 30628 (gringo) S 30618 30618 22717 34817 22717 4202496 405 0 0 0 0 0 0 0 25 0 1 0 72763830 2650112 272 1283457024 134512640 136933539 4290610768 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30628/statm: 647 272 242 592 0 52 0 [pid=30629] ppid=30618 vsize=26168 CPUtime=1.19 /proc/30629/stat : 30629 (cudf2lp) R 30618 30618 22717 34817 22717 4202496 7649 0 0 0 115 4 0 0 25 0 1 0 72763830 26796032 6050 1283457024 134512640 135786343 4291987296 18446744073709551615 134540554 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30629/statm: 6542 6050 128 311 0 6229 0 Current children cumulated CPU time (s) 1.19 Current children cumulated vsize (KiB) 33280 [startup+3.11369 s] /proc/loadavg: 1.16 1.07 1.01 2/37 30629 /proc/meminfo: memFree=441036/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.14 /proc/30618/stat : 30618 (aspcud-1.5) R 30617 30618 22717 34817 22717 4202496 580 17561 0 0 0 0 206 8 19 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=5760 CPUtime=0.49 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 1346 0 0 0 49 0 0 0 18 0 1 0 72763830 5898240 1212 1283457024 134512640 136285277 4288254864 18446744073709551615 134649426 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 1440 1212 234 433 0 1005 0 [pid=30628] ppid=30618 vsize=0 CPUtime=0.1 /proc/30628/stat : 30628 (gringo) Z 30618 30618 22717 34817 22717 4202508 1500 0 0 0 10 0 0 0 18 0 1 0 72763830 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/30628/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.73 Current children cumulated vsize (KiB) 8356 [startup+6.30429 s] /proc/loadavg: 1.16 1.07 1.01 2/35 30629 /proc/meminfo: memFree=481500/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=12172 CPUtime=3.68 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 2956 0 0 0 368 0 0 0 25 0 1 0 72763830 12464128 2822 1283457024 134512640 136285277 4288254864 18446744073709551615 134733707 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 3043 2822 234 433 0 2608 0 Current children cumulated CPU time (s) 5.93 Current children cumulated vsize (KiB) 14768 [startup+12.7056 s] /proc/loadavg: 1.15 1.07 1.01 2/35 30629 /proc/meminfo: memFree=477904/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=13560 CPUtime=10.07 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 3323 0 0 0 1007 0 0 0 25 0 1 0 72763830 13885440 3185 1283457024 134512640 136285277 4288254864 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 3390 3185 234 433 0 2955 0 Current children cumulated CPU time (s) 12.32 Current children cumulated vsize (KiB) 16156 [startup+25.5086 s] /proc/loadavg: 1.11 1.06 1.01 2/35 30629 /proc/meminfo: memFree=477284/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=14268 CPUtime=22.86 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 3546 0 0 0 2286 0 0 0 25 0 1 0 72763830 14610432 3340 1283457024 134512640 136285277 4288254864 18446744073709551615 134930669 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 3567 3340 234 433 0 3132 0 Current children cumulated CPU time (s) 25.11 Current children cumulated vsize (KiB) 16864 [startup+51.1043 s] /proc/loadavg: 1.07 1.06 1.01 2/35 30629 /proc/meminfo: memFree=475052/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=16332 CPUtime=48.43 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 4387 0 0 0 4843 0 0 0 25 0 1 0 72763830 16723968 3877 1283457024 134512640 136285277 4288254864 18446744073709551615 134686311 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 4083 3877 234 433 0 3648 0 Current children cumulated CPU time (s) 50.68 Current children cumulated vsize (KiB) 18928 [startup+102.314 s] /proc/loadavg: 1.03 1.04 1.00 2/35 30629 /proc/meminfo: memFree=474060/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=17500 CPUtime=99.63 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 4726 0 0 0 9963 0 0 0 25 0 1 0 72763830 17920000 4135 1283457024 134512640 136285277 4288254864 18446744073709551615 134686795 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 4375 4135 234 433 0 3940 0 Current children cumulated CPU time (s) 101.88 Current children cumulated vsize (KiB) 20096 [startup+162.307 s] /proc/loadavg: 1.01 1.03 1.00 2/35 30629 /proc/meminfo: memFree=472200/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=19128 CPUtime=159.57 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 5334 0 0 0 15955 2 0 0 25 0 1 0 72763830 19587072 4574 1283457024 134512640 136285277 4288254864 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 4782 4574 234 433 0 4347 0 Current children cumulated CPU time (s) 161.82 Current children cumulated vsize (KiB) 21724 [startup+222.312 s] /proc/loadavg: 1.00 1.03 1.00 2/37 30634 /proc/meminfo: memFree=469324/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=21704 CPUtime=219.52 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 6244 0 0 0 21950 2 0 0 25 0 1 0 72763830 22224896 5218 1283457024 134512640 136285277 4288254864 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 5426 5218 234 433 0 4991 0 Current children cumulated CPU time (s) 221.77 Current children cumulated vsize (KiB) 24300 [startup+282.306 s] /proc/loadavg: 1.00 1.02 1.00 2/37 30643 /proc/meminfo: memFree=468832/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=21808 CPUtime=279.43 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 6311 0 0 0 27941 2 0 0 25 0 1 0 72763830 22331392 5244 1283457024 134512640 136285277 4288254864 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 5452 5244 234 433 0 5017 0 Current children cumulated CPU time (s) 281.68 Current children cumulated vsize (KiB) 24404 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.708 s] /proc/loadavg: 1.00 1.02 1.00 2/36 30643 /proc/meminfo: memFree=468848/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=21808 CPUtime=287.82 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 6311 0 0 0 28780 2 0 0 25 0 1 0 72763830 22331392 5244 1283457024 134512640 136285277 4288254864 18446744073709551615 134650189 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 5452 5244 234 433 0 5017 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 24404 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.708 s] /proc/loadavg: 1.00 1.02 1.00 2/36 30643 /proc/meminfo: memFree=468848/1048576 swapFree=0/0 [pid=30618] ppid=30617 vsize=2596 CPUtime=2.25 /proc/30618/stat : 30618 (aspcud-1.5) S 30617 30618 22717 34817 22717 4202496 580 19061 0 0 0 0 217 8 16 0 1 0 72763829 2658304 299 1283457024 134512640 135304128 4287726256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30618/statm: 649 299 251 194 0 36 0 [pid=30627] ppid=30618 vsize=21808 CPUtime=287.82 /proc/30627/stat : 30627 (clasp) R 30618 30618 22717 34817 22717 4202496 6311 0 0 0 28780 2 0 0 25 0 1 0 72763830 22331392 5244 1283457024 134512640 136285277 4288254864 18446744073709551615 134650189 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30627/statm: 5452 5244 234 433 0 5017 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 24404 Child status: 0 Real time (s): 290.729 CPU time (s): 290.11 CPU user time (s): 289.982 CPU system time (s): 0.128008 CPU usage (%): 99.787 Max. virtual memory (cumulated for all children) (KiB): 62276 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.982 system time used= 0.128008 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 29495 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= 244 involuntary context switches= 3771 runsolver used 0.008 second user time and 0 second system time The end