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/201108291842/aspuncud-user-1.0/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /home/misc2010/tmp/201108291842/aspuncud-user-1.0/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.dudf-real.result -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.06 1.14 1.17 1/35 27921
/proc/meminfo: memFree=941252/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=3016 CPUtime=0
/proc/27921/stat : 27921 (runsolver) D 27920 27921 17511 34816 17511 4202560 72 0 0 0 0 0 0 0 25 0 1 0 46512322 3088384 93 1283457024 134512640 134586868 4292570784 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/27921/statm: 754 93 62 19 0 53 0

[startup+0.125467 s]
/proc/loadavg: 1.06 1.14 1.17 1/35 27921
/proc/meminfo: memFree=941252/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=0
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.205447 s]
/proc/loadavg: 1.06 1.14 1.17 1/35 27921
/proc/meminfo: memFree=941252/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=0
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.305444 s]
/proc/loadavg: 1.06 1.14 1.17 1/35 27921
/proc/meminfo: memFree=941252/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=0
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.707653 s]
/proc/loadavg: 1.06 1.14 1.17 1/35 27921
/proc/meminfo: memFree=941252/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=0
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+1.5079 s]
/proc/loadavg: 1.05 1.14 1.17 2/39 27932
/proc/meminfo: memFree=915480/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=0
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=3448 CPUtime=0
/proc/27930/stat : 27930 (unclasp) S 27921 27921 17511 34816 17511 4202496 402 0 5 0 0 0 0 0 25 0 1 0 46512327 3530752 272 1283457024 134512640 135121179 4288550000 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27930/statm: 862 272 240 149 0 53 0
[pid=27931] ppid=27921 vsize=2688 CPUtime=0
/proc/27931/stat : 27931 (gringo) S 27921 27921 17511 34816 17511 4202496 384 0 23 0 0 0 0 0 24 0 1 0 46512327 2752512 280 1283457024 134512640 137056543 4288557296 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27931/statm: 672 280 252 622 0 47 0
[pid=27932] ppid=27921 vsize=25196 CPUtime=1.29
/proc/27932/stat : 27932 (cudf2lp) R 27921 27921 17511 34816 17511 4202496 7357 0 15 0 126 3 0 0 25 0 1 0 46512327 25800704 5779 1283457024 134512640 135786343 4288702944 18446744073709551615 134614180 0 0 6 0 0 0 0 17 0 0 0 0
/proc/27932/statm: 6299 5779 128 311 0 5986 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 33920

[startup+3.10837 s]
/proc/loadavg: 1.05 1.14 1.17 2/39 27932
/proc/meminfo: memFree=889688/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=22780 CPUtime=0.11
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 5650 0 7 0 10 1 0 0 18 0 1 0 46512327 23326720 5000 1283457024 134512640 135121179 4288550000 18446744073709551615 134702595 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 5695 5000 290 149 0 4886 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 25368

[startup+6.30928 s]
/proc/loadavg: 1.05 1.14 1.17 2/37 27933
/proc/meminfo: memFree=911916/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29376 CPUtime=3.31
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 18675 0 7 0 327 4 0 0 25 0 1 0 46512327 30081024 6483 1283457024 134512640 135121179 4288550000 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7344 6483 333 149 0 6535 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 31964

[startup+12.7112 s]
/proc/loadavg: 1.04 1.13 1.16 2/37 27933
/proc/meminfo: memFree=911676/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29376 CPUtime=9.71
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 64447 0 7 0 937 34 0 0 25 0 1 0 46512327 30081024 6491 1283457024 134512640 135121179 4288550000 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7344 6491 333 149 0 6535 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 31964

[startup+25.5068 s]
/proc/loadavg: 1.04 1.13 1.16 2/37 27935
/proc/meminfo: memFree=911192/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=30020 CPUtime=22.5
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 181649 0 7 0 2166 84 0 0 25 0 1 0 46512327 30740480 6615 1283457024 134512640 135121179 4288550000 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7505 6615 333 149 0 6696 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 32608

Solver just ended. Dumping a history of the last processes samples

[startup+25.6069 s]
/proc/loadavg: 1.04 1.13 1.16 2/37 27935
/proc/meminfo: memFree=911192/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=30020 CPUtime=22.6
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 181649 0 7 0 2176 84 0 0 25 0 1 0 46512327 30740480 6615 1283457024 134512640 135121179 4288550000 18446744073709551615 134959070 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7505 6615 333 149 0 6696 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 32608

[startup+32.0091 s]
/proc/loadavg: 1.03 1.12 1.16 2/37 27935
/proc/meminfo: memFree=911192/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=30020 CPUtime=29
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 181649 0 7 0 2814 86 0 0 25 0 1 0 46512327 30740480 6615 1283457024 134512640 135121179 4288550000 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7505 6615 333 149 0 6696 0
Current children cumulated CPU time (s) 31.76
Current children cumulated vsize (KiB) 32608

[startup+38.4119 s]
/proc/loadavg: 1.03 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911208/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29376 CPUtime=35.4
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 230832 0 7 0 3428 112 0 0 25 0 1 0 46512327 30081024 6491 1283457024 134512640 135121179 4288550000 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7344 6491 333 149 0 6535 0
Current children cumulated CPU time (s) 38.16
Current children cumulated vsize (KiB) 31964

[startup+41.6133 s]
/proc/loadavg: 1.03 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911208/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29924 CPUtime=38.59
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 258369 0 7 0 3735 124 0 0 25 0 1 0 46512327 30642176 6628 1283457024 134512640 135121179 4288550000 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7481 6628 333 149 0 6672 0
Current children cumulated CPU time (s) 41.35
Current children cumulated vsize (KiB) 32512

[startup+43.214 s]
/proc/loadavg: 1.02 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911208/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29376 CPUtime=40.19
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 271932 0 7 0 3889 130 0 0 25 0 1 0 46512327 30081024 6491 1283457024 134512640 135121179 4288550000 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7344 6491 333 149 0 6535 0
Current children cumulated CPU time (s) 42.95
Current children cumulated vsize (KiB) 31964

[startup+44.0043 s]
/proc/loadavg: 1.02 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911828/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=28748 CPUtime=40.99
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 278961 0 7 0 3958 141 0 0 25 0 1 0 46512327 29437952 6334 1283457024 134512640 135121179 4288550000 18446744073709551615 134734462 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7187 6334 333 149 0 6378 0
Current children cumulated CPU time (s) 43.75
Current children cumulated vsize (KiB) 31336

[startup+44.4045 s]
/proc/loadavg: 1.02 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911828/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=29296 CPUtime=41.38
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202496 283327 0 7 0 3994 144 0 0 25 0 1 0 46512327 29999104 6464 1283457024 134512640 135121179 4288550000 18446744073709551615 134990541 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 7324 6464 333 149 0 6515 0
Current children cumulated CPU time (s) 44.14
Current children cumulated vsize (KiB) 31884

[startup+44.5045 s]
/proc/loadavg: 1.02 1.12 1.16 2/36 27935
/proc/meminfo: memFree=911828/1048576 swapFree=0/0
[pid=27921] ppid=27920 vsize=2588 CPUtime=2.76
/proc/27921/stat : 27921 (aspuncud-user-1) S 27920 27921 17511 34816 17511 4202496 567 22032 0 41 0 0 260 16 16 0 1 0 46512322 2650112 297 1283457024 134512640 135304128 4294082800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27921/statm: 647 297 251 194 0 34 0
[pid=27930] ppid=27921 vsize=0 CPUtime=41.49
/proc/27930/stat : 27930 (unclasp) R 27921 27921 17511 34816 17511 4202500 283978 0 7 0 4003 146 0 0 25 0 1 0 46512327 0 0 1283457024 0 0 0 0 0 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27930/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.25
Current children cumulated vsize (KiB) 2588

Child status: 0
Real time (s): 44.5453
CPU time (s): 44.2628
CPU user time (s): 42.6387
CPU system time (s): 1.6241
CPU usage (%): 99.3657
Max. virtual memory (cumulated for all children) (KiB): 70304

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 42.6387
system time used= 1.6241
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 309183
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1313
involuntary context switches= 1441

runsolver used 0 second user time and 0 second system time

The end