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/201108300820/aspuncud-user-1.0/0207e19a-9b1c-11df-af69-00163e46d37a.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//0207e19a-9b1c-11df-af69-00163e46d37a.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/0207e19a-9b1c-11df-af69-00163e46d37a.cudf.dudf-real.result +sum(installedsize) 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 0.99 0.73 3/33 2412 /proc/meminfo: memFree=943264/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=3020 CPUtime=0 /proc/2412/stat : 2412 (runsolver) D 2411 2412 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 23 0 1 0 50976930 3092480 93 1283457024 134512640 134586868 4292583088 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/2412/statm: 755 93 62 19 0 54 0 [startup+0.120061 s] /proc/loadavg: 1.00 0.99 0.73 3/33 2412 /proc/meminfo: memFree=943264/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.204061 s] /proc/loadavg: 1.00 0.99 0.73 3/33 2412 /proc/meminfo: memFree=943264/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.304058 s] /proc/loadavg: 1.00 0.99 0.73 3/33 2412 /proc/meminfo: memFree=943264/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.704679 s] /proc/loadavg: 1.00 0.99 0.73 3/33 2412 /proc/meminfo: memFree=943264/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.50485 s] /proc/loadavg: 1.00 0.99 0.73 2/37 2423 /proc/meminfo: memFree=918144/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=3448 CPUtime=0 /proc/2421/stat : 2421 (unclasp) S 2412 2412 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 50976935 3530752 272 1283457024 134512640 135121179 4288050992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2421/statm: 862 272 240 149 0 53 0 [pid=2422] ppid=2412 vsize=2696 CPUtime=0 /proc/2422/stat : 2422 (gringo) S 2412 2412 2160 34817 2160 4202496 386 0 22 0 0 0 0 0 23 0 1 0 50976935 2760704 281 1283457024 134512640 137056543 4289604832 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2422/statm: 674 281 252 622 0 49 0 [pid=2423] ppid=2412 vsize=26540 CPUtime=1.26 /proc/2423/stat : 2423 (cudf2lp) R 2412 2412 2160 34817 2160 4202496 7742 0 15 0 121 5 0 0 25 0 1 0 50976935 27176960 6011 1283457024 134512640 135786343 4294920800 18446744073709551615 135196000 0 0 6 0 0 0 0 17 0 0 0 0 /proc/2423/statm: 6635 6011 128 311 0 6322 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 35272 [startup+3.10526 s] /proc/loadavg: 1.00 0.99 0.73 2/37 2423 /proc/meminfo: memFree=890244/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=0 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 1518 0 3 0 0 0 0 25 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=22564 CPUtime=0.03 /proc/2421/stat : 2421 (unclasp) S 2412 2412 2160 34817 2160 4202496 6091 0 6 0 2 1 0 0 18 0 1 0 50976935 23105536 4898 1283457024 134512640 135121179 4288050992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2421/statm: 5641 4898 275 149 0 4832 0 [pid=2422] ppid=2412 vsize=31048 CPUtime=1.04 /proc/2422/stat : 2422 (gringo) R 2412 2412 2160 34817 2160 4202496 9254 0 22 0 100 4 0 0 18 0 1 0 50976935 31793152 5952 1283457024 134512640 137056543 4289604832 18446744073709551615 136312748 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2422/statm: 7762 5952 253 622 0 7137 0 [pid=2423] ppid=2412 vsize=35608 CPUtime=1.77 /proc/2423/stat : 2423 (cudf2lp) R 2412 2412 2160 34817 2160 4202496 11437 0 15 0 171 6 0 0 25 0 1 0 50976935 36462592 8691 1283457024 134512640 135786343 4294920800 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/2423/statm: 8902 8691 139 311 0 8589 0 Current children cumulated CPU time (s) 2.84 Current children cumulated vsize (KiB) 91808 [startup+6.30587 s] /proc/loadavg: 1.08 1.01 0.73 2/36 2423 /proc/meminfo: memFree=814628/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=2.04 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 12958 0 18 0 0 196 8 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=73980 CPUtime=0.4 /proc/2421/stat : 2421 (unclasp) S 2412 2412 2160 34817 2160 4202496 20263 0 6 0 36 4 0 0 18 0 1 0 50976935 75755520 17624 1283457024 134512640 135121179 4288050992 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2421/statm: 18495 17624 279 149 0 17686 0 [pid=2422] ppid=2412 vsize=122300 CPUtime=3.6 /proc/2422/stat : 2422 (gringo) R 2412 2412 2160 34817 2160 4202496 37270 0 22 0 346 14 0 0 19 0 1 0 50976935 125235200 24912 1283457024 134512640 137056543 4289604832 18446744073709551615 134548563 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2422/statm: 30575 24912 268 622 0 29950 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 198868 [startup+12.7085 s] /proc/loadavg: 1.07 1.00 0.73 2/35 2423 /proc/meminfo: memFree=848620/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=99604 CPUtime=6.44 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 104913 0 7 0 598 46 0 0 25 0 1 0 50976935 101994496 22955 1283457024 134512640 135121179 4288050992 18446744073709551615 4159173701 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24901 22955 319 149 0 24092 0 Current children cumulated CPU time (s) 12.43 Current children cumulated vsize (KiB) 102192 [startup+25.5028 s] /proc/loadavg: 1.06 1.00 0.74 2/35 2423 /proc/meminfo: memFree=848496/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=99608 CPUtime=19.24 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 280684 0 7 0 1796 128 0 0 25 0 1 0 50976935 101998592 22969 1283457024 134512640 135121179 4288050992 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24902 22969 319 149 0 24093 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 102196 [startup+51.1121 s] /proc/loadavg: 1.04 1.00 0.74 2/35 2423 /proc/meminfo: memFree=845644/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=101168 CPUtime=44.83 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 624586 0 7 0 4209 274 0 0 25 0 1 0 50976935 103596032 23401 1283457024 134512640 135121179 4288050992 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 25292 23401 321 149 0 24483 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 103756 [startup+102.312 s] /proc/loadavg: 1.01 1.00 0.75 2/35 2423 /proc/meminfo: memFree=847132/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=99616 CPUtime=96.01 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 1301362 0 7 0 9026 575 0 0 25 0 1 0 50976935 102006784 23045 1283457024 134512640 135121179 4288050992 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24904 23045 321 149 0 24095 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 102204 [startup+162.305 s] /proc/loadavg: 1.00 1.00 0.76 2/35 2423 /proc/meminfo: memFree=846884/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=99620 CPUtime=155.96 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 2072606 0 7 0 14684 912 0 0 25 0 1 0 50976935 102010880 23078 1283457024 134512640 135121179 4288050992 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24905 23078 321 149 0 24096 0 Current children cumulated CPU time (s) 161.95 Current children cumulated vsize (KiB) 102208 [startup+222.315 s] /proc/loadavg: 1.00 1.00 0.77 2/35 2423 /proc/meminfo: memFree=846636/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=98796 CPUtime=215.9 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 2824321 0 7 0 20348 1242 0 0 25 0 1 0 50976935 101167104 22899 1283457024 134512640 135121179 4288050992 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24699 22899 321 149 0 23890 0 Current children cumulated CPU time (s) 221.89 Current children cumulated vsize (KiB) 101384 [startup+282.315 s] /proc/loadavg: 1.00 1.00 0.79 2/37 2430 /proc/meminfo: memFree=846736/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=98840 CPUtime=275.88 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 3620764 0 7 0 25996 1592 0 0 25 0 1 0 50976935 101212160 22953 1283457024 134512640 135121179 4288050992 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 24710 22953 321 149 0 23901 0 Current children cumulated CPU time (s) 281.87 Current children cumulated vsize (KiB) 101428 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.508 s] /proc/loadavg: 1.00 1.00 0.79 2/37 2431 /proc/meminfo: memFree=844504/1048576 swapFree=0/0 [pid=2412] ppid=2411 vsize=2588 CPUtime=5.99 /proc/2412/stat : 2412 (aspuncud-user-1) S 2411 2412 2160 34817 2160 4202496 570 50231 0 40 0 0 574 25 18 0 1 0 50976930 2650112 297 1283457024 134512640 135304128 4290112816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2412/statm: 647 297 251 194 0 34 0 [pid=2421] ppid=2412 vsize=101644 CPUtime=284.06 /proc/2421/stat : 2421 (unclasp) R 2412 2412 2160 34817 2160 4202496 3736764 0 7 0 26769 1637 0 0 25 0 1 0 50976935 104083456 23696 1283457024 134512640 135121179 4288050992 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2421/statm: 25411 23696 321 149 0 24602 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 104232 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.546 CPU time (s): 290.082 CPU user time (s): 273.441 CPU system time (s): 16.641 CPU usage (%): 99.8404 Max. virtual memory (cumulated for all children) (KiB): 198868 getrusage(RUSAGE_CHILDREN,...) data: user time used= 273.441 system time used= 16.641 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 3789940 page faults= 49 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 6786 involuntary context switches= 8846 runsolver used 0 second user time and 0 second system time The end