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/aspuncud-user-1.0/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf /home/misc2010/tmp/201109011757/aspuncud-user-1.0/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.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.00 1.00 0.92 5/39 24754 /proc/meminfo: memFree=627416/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2584 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 372 0 0 0 0 0 0 0 18 0 1 0 71921465 2646016 279 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/24751/statm: 646 279 234 194 0 33 0 [pid=24752] ppid=24751 vsize=2584 CPUtime=0 /proc/24752/stat : 24752 (aspuncud-user-1) S 24751 24751 22717 34817 22717 4202560 118 0 0 0 0 0 0 0 18 0 1 0 71921465 2646016 133 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/24752/statm: 646 133 87 194 0 33 0 [pid=24753] ppid=24752 vsize=2584 CPUtime=0 /proc/24753/stat : 24753 (aspuncud-user-1) R 24752 24751 22717 34817 22717 4202560 127 0 0 0 0 0 0 0 25 0 1 0 71921465 2646016 150 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24753/statm: 646 150 104 194 0 33 0 [pid=24754] ppid=24753 vsize=2584 CPUtime=0 /proc/24754/stat : 24754 (aspuncud-user-1) R 24753 24751 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 71921465 2646016 46 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24754/statm: 646 46 0 194 0 33 0 [startup+0.135015 s] /proc/loadavg: 1.00 1.00 0.92 5/39 24754 /proc/meminfo: memFree=627416/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) R 24750 24751 22717 34817 22717 4202496 546 1520 0 0 0 0 0 0 25 0 1 0 71921465 2650112 296 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/24751/statm: 647 296 250 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.205035 s] /proc/loadavg: 1.00 1.00 0.92 5/39 24754 /proc/meminfo: memFree=627416/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 1520 0 0 0 0 0 0 25 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.305073 s] /proc/loadavg: 1.00 1.00 0.92 5/39 24754 /proc/meminfo: memFree=627416/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 1520 0 0 0 0 0 0 25 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.705121 s] /proc/loadavg: 1.00 1.00 0.92 5/39 24754 /proc/meminfo: memFree=627416/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 1520 0 0 0 0 0 0 25 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.50523 s] /proc/loadavg: 1.00 1.00 0.92 2/40 24762 /proc/meminfo: memFree=603100/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=0 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 1520 0 0 0 0 0 0 25 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=3440 CPUtime=0 /proc/24760/stat : 24760 (unclasp) S 24751 24751 22717 34817 22717 4202496 406 0 0 0 0 0 0 0 25 0 1 0 71921466 3522560 271 1283457024 134512640 135121179 4289187056 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24760/statm: 860 271 240 149 0 51 0 [pid=24761] ppid=24751 vsize=2696 CPUtime=0 /proc/24761/stat : 24761 (gringo) S 24751 24751 22717 34817 22717 4202496 408 0 0 0 0 0 0 0 25 0 1 0 71921466 2760704 281 1283457024 134512640 137056543 4290590160 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24761/statm: 674 281 252 622 0 49 0 [pid=24762] ppid=24751 vsize=40644 CPUtime=1.49 /proc/24762/stat : 24762 (cudf2lp) R 24751 24751 22717 34817 22717 4202496 11357 0 0 0 144 5 0 0 25 0 1 0 71921466 41619456 9618 1283457024 134512640 135786343 4289184928 18446744073709551615 135196013 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24762/statm: 10161 9618 135 311 0 9848 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 49368 [startup+3.10547 s] /proc/loadavg: 1.00 1.00 0.92 2/40 24762 /proc/meminfo: memFree=595908/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=0.63 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 8848 0 0 0 59 4 0 0 18 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 30892 [startup+6.30655 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28664 CPUtime=3.83 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 28869 0 0 0 372 11 0 0 25 0 1 0 71921466 29351936 6284 1283457024 134512640 135121179 4289187056 18446744073709551615 4157995798 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7166 6284 328 149 0 6357 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 31252 [startup+12.7086 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28448 CPUtime=10.22 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 68348 0 0 0 999 23 0 0 25 0 1 0 71921466 29130752 6262 1283457024 134512640 135121179 4289187056 18446744073709551615 134982644 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7112 6262 328 149 0 6303 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 31036 Solver just ended. Dumping a history of the last processes samples [startup+12.8087 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=10.32 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 69040 0 0 0 1009 23 0 0 25 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 12.77 Current children cumulated vsize (KiB) 30892 [startup+19.2106 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28664 CPUtime=16.72 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 107196 0 0 0 1633 39 0 0 25 0 1 0 71921466 29351936 6302 1283457024 134512640 135121179 4289187056 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7166 6302 328 149 0 6357 0 Current children cumulated CPU time (s) 19.17 Current children cumulated vsize (KiB) 31252 [startup+20.811 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28664 CPUtime=18.32 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 116799 0 0 0 1785 47 0 0 25 0 1 0 71921466 29351936 6302 1283457024 134512640 135121179 4289187056 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7166 6302 328 149 0 6357 0 Current children cumulated CPU time (s) 20.77 Current children cumulated vsize (KiB) 31252 [startup+22.4117 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=19.92 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 126361 0 0 0 1943 49 0 0 25 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 22.37 Current children cumulated vsize (KiB) 30892 [startup+23.212 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=20.71 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 131113 0 0 0 2020 51 0 0 25 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 23.16 Current children cumulated vsize (KiB) 30892 [startup+23.4121 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=20.91 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 132301 0 0 0 2039 52 0 0 25 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 23.36 Current children cumulated vsize (KiB) 30892 [startup+23.5122 s] /proc/loadavg: 1.00 1.00 0.92 2/38 24762 /proc/meminfo: memFree=603008/1048576 swapFree=0/0 [pid=24751] ppid=24750 vsize=2588 CPUtime=2.45 /proc/24751/stat : 24751 (aspuncud-user-1) S 24750 24751 22717 34817 22717 4202496 571 20965 0 0 0 0 233 12 16 0 1 0 71921465 2650112 297 1283457024 134512640 135304128 4294398192 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24751/statm: 647 297 251 194 0 34 0 [pid=24760] ppid=24751 vsize=28304 CPUtime=21.01 /proc/24760/stat : 24760 (unclasp) R 24751 24751 22717 34817 22717 4202496 132895 0 0 0 2049 52 0 0 25 0 1 0 71921466 28983296 6261 1283457024 134512640 135121179 4289187056 18446744073709551615 134694051 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24760/statm: 7076 6261 328 149 0 6267 0 Current children cumulated CPU time (s) 23.46 Current children cumulated vsize (KiB) 30892 Child status: 0 Real time (s): 23.5864 CPU time (s): 23.5575 CPU user time (s): 22.8934 CPU system time (s): 0.664041 CPU usage (%): 99.8773 Max. virtual memory (cumulated for all children) (KiB): 63084 getrusage(RUSAGE_CHILDREN,...) data: user time used= 22.8934 system time used= 0.664041 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 157078 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= 1165 involuntary context switches= 1124 runsolver used 0 second user time and 0.008 second system time The end