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/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/7c834c0e-51b8-11e0-a49e-00163e1e087d.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.02 1.05 1.02 3/33 12901
/proc/meminfo: memFree=945672/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=3020 CPUtime=0
/proc/12901/stat : 12901 (runsolver) D 12900 12901 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 23 0 1 0 56533155 3092480 94 1283457024 134512640 134586868 4293218128 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/12901/statm: 755 94 62 19 0 54 0

[startup+0.188087 s]
/proc/loadavg: 1.02 1.05 1.02 3/33 12901
/proc/meminfo: memFree=945672/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.204085 s]
/proc/loadavg: 1.02 1.05 1.02 3/33 12901
/proc/meminfo: memFree=945672/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.304075 s]
/proc/loadavg: 1.02 1.05 1.02 3/33 12901
/proc/meminfo: memFree=945672/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.70574 s]
/proc/loadavg: 1.02 1.05 1.02 3/33 12901
/proc/meminfo: memFree=945672/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5059 s]
/proc/loadavg: 1.02 1.05 1.02 2/37 12912
/proc/meminfo: memFree=925572/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=3444 CPUtime=0
/proc/12910/stat : 12910 (unclasp) S 12901 12901 2160 34817 2160 4202496 401 0 5 0 0 0 0 0 23 0 1 0 56533160 3526656 271 1283457024 134512640 135121179 4289882560 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12910/statm: 861 271 240 149 0 52 0
[pid=12911] ppid=12901 vsize=2696 CPUtime=0
/proc/12911/stat : 12911 (gringo) S 12901 12901 2160 34817 2160 4202496 386 0 22 0 0 0 0 0 23 0 1 0 56533160 2760704 281 1283457024 134512640 137056543 4288186160 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12911/statm: 674 281 252 622 0 49 0
[pid=12912] ppid=12901 vsize=31520 CPUtime=1.2
/proc/12912/stat : 12912 (cudf2lp) R 12901 12901 2160 34817 2160 4202496 8789 0 15 0 118 2 0 0 25 0 1 0 56533161 32276480 7163 1283457024 134512640 135786343 4288526832 18446744073709551615 135195152 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12912/statm: 7880 7163 135 311 0 7567 0
Current children cumulated CPU time (s) 1.2
Current children cumulated vsize (KiB) 40252

[startup+3.1063 s]
/proc/loadavg: 1.02 1.05 1.02 3/37 12912
/proc/meminfo: memFree=892216/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=0
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 1517 0 3 0 0 0 0 25 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=23488 CPUtime=0.1
/proc/12910/stat : 12910 (unclasp) S 12901 12901 2160 34817 2160 4202496 6324 0 6 0 6 4 0 0 18 0 1 0 56533160 24051712 5131 1283457024 134512640 135121179 4289882560 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12910/statm: 5872 5131 275 149 0 5063 0
[pid=12911] ppid=12901 vsize=32100 CPUtime=1.11
/proc/12911/stat : 12911 (gringo) R 12901 12901 2160 34817 2160 4202496 9643 0 22 0 101 10 0 0 18 0 1 0 56533160 32870400 6341 1283457024 134512640 137056543 4288186160 18446744073709551615 134903527 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12911/statm: 8025 6341 253 622 0 7400 0
[pid=12912] ppid=12901 vsize=32752 CPUtime=1.57
/proc/12912/stat : 12912 (cudf2lp) R 12901 12901 2160 34817 2160 4202496 10520 0 15 0 155 2 0 0 25 0 1 0 56533161 33538048 7989 1283457024 134512640 135786343 4288526832 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12912/statm: 8188 7989 139 311 0 7875 0
Current children cumulated CPU time (s) 2.78
Current children cumulated vsize (KiB) 90932

[startup+6.31275 s]
/proc/loadavg: 1.09 1.07 1.02 2/36 12912
/proc/meminfo: memFree=803200/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=77176 CPUtime=0.89
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 21905 0 7 0 77 12 0 0 18 0 1 0 56533160 79028224 18385 1283457024 134512640 135121179 4289882560 18446744073709551615 134747624 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 19294 18385 299 149 0 18485 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 79768

[startup+12.7146 s]
/proc/loadavg: 1.09 1.06 1.02 2/35 12912
/proc/meminfo: memFree=861816/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=87824 CPUtime=7.29
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 125560 0 7 0 681 48 0 0 25 0 1 0 56533160 89931776 20218 1283457024 134512640 135121179 4289882560 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 21956 20218 319 149 0 21147 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 90416

[startup+25.5093 s]
/proc/loadavg: 1.07 1.06 1.02 2/37 12914
/proc/meminfo: memFree=859064/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=87368 CPUtime=20.07
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 326413 0 7 0 1872 135 0 0 25 0 1 0 56533160 89464832 20081 1283457024 134512640 135121179 4289882560 18446744073709551615 4159943749 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 21842 20081 319 149 0 21033 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 89960

[startup+51.108 s]
/proc/loadavg: 1.04 1.05 1.02 2/37 12916
/proc/meminfo: memFree=860304/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=87376 CPUtime=45.65
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 727619 0 7 0 4274 291 0 0 25 0 1 0 56533160 89473024 20100 1283457024 134512640 135121179 4289882560 18446744073709551615 4159943781 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 21844 20100 321 149 0 21035 0
Current children cumulated CPU time (s) 50.74
Current children cumulated vsize (KiB) 89968

[startup+102.306 s]
/proc/loadavg: 1.02 1.04 1.02 2/37 12921
/proc/meminfo: memFree=859188/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=89988 CPUtime=96.81
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 1497152 0 7 0 9060 621 0 0 25 0 1 0 56533160 92147712 20760 1283457024 134512640 135121179 4289882560 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22497 20760 321 149 0 21688 0
Current children cumulated CPU time (s) 101.9
Current children cumulated vsize (KiB) 92580

[startup+162.308 s]
/proc/loadavg: 1.00 1.03 1.01 2/36 12923
/proc/meminfo: memFree=860072/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=90176 CPUtime=156.74
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 2335357 0 7 0 14690 984 0 0 25 0 1 0 56533160 92340224 20886 1283457024 134512640 135121179 4289882560 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22544 20886 321 149 0 21735 0
Current children cumulated CPU time (s) 161.83
Current children cumulated vsize (KiB) 92768

[startup+222.306 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 12923
/proc/meminfo: memFree=858468/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=88128 CPUtime=216.69
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 3114663 0 7 0 20372 1297 0 0 25 0 1 0 56533160 90243072 20397 1283457024 134512640 135121179 4289882560 18446744073709551615 134891059 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22032 20397 321 149 0 21223 0
Current children cumulated CPU time (s) 221.78
Current children cumulated vsize (KiB) 90720

[startup+282.309 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 12923
/proc/meminfo: memFree=858220/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=88136 CPUtime=276.65
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 3877738 0 7 0 26049 1616 0 0 25 0 1 0 56533160 90251264 20423 1283457024 134512640 135121179 4289882560 18446744073709551615 134734280 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22034 20423 321 149 0 21225 0
Current children cumulated CPU time (s) 281.74
Current children cumulated vsize (KiB) 90728



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.612 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 12923
/proc/meminfo: memFree=859584/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=88136 CPUtime=284.95
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 3983081 0 7 0 26840 1655 0 0 25 0 1 0 56533160 90251264 20425 1283457024 134512640 135121179 4289882560 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22034 20425 321 149 0 21225 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 90728

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.612 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 12923
/proc/meminfo: memFree=859584/1048576 swapFree=0/0
[pid=12901] ppid=12900 vsize=2592 CPUtime=5.09
/proc/12901/stat : 12901 (aspuncud-user-1) S 12900 12901 2160 34817 2160 4202496 572 45366 0 40 0 0 485 24 18 0 1 0 56533155 2654208 297 1283457024 134512640 135304128 4288445328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12901/statm: 648 297 251 194 0 35 0
[pid=12910] ppid=12901 vsize=88136 CPUtime=284.95
/proc/12910/stat : 12910 (unclasp) R 12901 12901 2160 34817 2160 4202496 3983081 0 7 0 26840 1655 0 0 25 0 1 0 56533160 90251264 20425 1283457024 134512640 135121179 4289882560 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12910/statm: 22034 20425 321 149 0 21225 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 90728

Child status: 0
Real time (s): 290.654
CPU time (s): 290.074
CPU user time (s): 273.265
CPU system time (s): 16.8091
CPU usage (%): 99.8004
Max. virtual memory (cumulated for all children) (KiB): 180468

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 273.265
system time used= 16.809
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 4031399
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= 5917
involuntary context switches= 8160

runsolver used 0 second user time and 0.004 second system time

The end