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/rand461.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand461.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand461.cudf.dudf-random.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 1.02 1.00 2/36 6960
/proc/meminfo: memFree=930936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=3020 CPUtime=0
/proc/6960/stat : 6960 (runsolver) D 6959 6960 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 24 0 1 0 53357104 3092480 93 1283457024 134512640 134586868 4288596800 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/6960/statm: 755 93 62 19 0 54 0

[startup+0.169723 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 6960
/proc/meminfo: memFree=930936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205726 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 6960
/proc/meminfo: memFree=930936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305727 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 6960
/proc/meminfo: memFree=930936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.708027 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 6960
/proc/meminfo: memFree=930936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50814 s]
/proc/loadavg: 1.00 1.02 1.00 2/40 6971
/proc/meminfo: memFree=911952/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=3444 CPUtime=0
/proc/6969/stat : 6969 (unclasp) S 6960 6960 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 24 0 1 0 53357108 3526656 272 1283457024 134512640 135121179 4288210320 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6969/statm: 861 272 240 149 0 52 0
[pid=6970] ppid=6960 vsize=2688 CPUtime=0
/proc/6970/stat : 6970 (gringo) S 6960 6960 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 23 0 1 0 53357108 2752512 280 1283457024 134512640 137056543 4288212448 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6970/statm: 672 280 252 622 0 47 0
[pid=6971] ppid=6960 vsize=27484 CPUtime=1.28
/proc/6971/stat : 6971 (cudf2lp) R 6960 6960 2160 34817 2160 4202496 7564 0 15 0 125 3 0 0 25 0 1 0 53357108 28143616 6083 1283457024 134512640 135786343 4290658640 18446744073709551615 135220089 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6971/statm: 6871 6083 128 311 0 6558 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36212

[startup+3.10834 s]
/proc/loadavg: 1.00 1.02 1.00 2/40 6971
/proc/meminfo: memFree=886160/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=0
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=13004 CPUtime=0.06
/proc/6969/stat : 6969 (unclasp) S 6960 6960 2160 34817 2160 4202496 3165 0 6 0 5 1 0 0 18 0 1 0 53357108 13316096 2649 1283457024 134512640 135121179 4288210320 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6969/statm: 3251 2649 275 149 0 2442 0
[pid=6970] ppid=6960 vsize=17320 CPUtime=0.49
/proc/6970/stat : 6970 (gringo) R 6960 6960 2160 34817 2160 4202496 4802 0 23 0 47 2 0 0 18 0 1 0 53357108 17735680 3264 1283457024 134512640 137056543 4288212448 18446744073709551615 134608504 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6970/statm: 4330 3264 253 622 0 3705 0
[pid=6971] ppid=6960 vsize=43700 CPUtime=2.31
/proc/6971/stat : 6971 (cudf2lp) R 6960 6960 2160 34817 2160 4202496 13483 0 15 0 226 5 0 0 25 0 1 0 53357108 44748800 10732 1283457024 134512640 135786343 4290658640 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6971/statm: 10925 10732 139 311 0 10612 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 76620

[startup+6.30944 s]
/proc/loadavg: 1.00 1.02 1.00 3/40 6971
/proc/meminfo: memFree=794836/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=2.95
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 15005 0 18 0 0 289 6 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=52852 CPUtime=0.2
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 15204 0 6 0 16 4 0 0 18 0 1 0 53357108 54120448 12392 1283457024 134512640 135121179 4288210320 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 13213 12392 276 149 0 12404 0
[pid=6970] ppid=6960 vsize=74900 CPUtime=2.9
/proc/6970/stat : 6970 (gringo) R 6960 6960 2160 34817 2160 4202496 25230 0 23 0 282 8 0 0 18 0 1 0 53357108 76697600 15098 1283457024 134512640 137056543 4288212448 18446744073709551615 134903320 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6970/statm: 18725 15098 268 622 0 18100 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 130348

[startup+12.7118 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 6971
/proc/meminfo: memFree=805284/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=134608 CPUtime=4.42
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 89682 0 7 0 409 33 0 0 25 0 1 0 53357108 137838592 31295 1283457024 134512640 135121179 4288210320 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 33652 31295 319 149 0 32843 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 137204

[startup+25.5062 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 6971
/proc/meminfo: memFree=805284/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=130912 CPUtime=17.2
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 324239 0 7 0 1590 130 0 0 25 0 1 0 53357108 134053888 30377 1283457024 134512640 135121179 4288210320 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32728 30377 319 149 0 31919 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 133508

[startup+51.1144 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 6971
/proc/meminfo: memFree=801936/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=130920 CPUtime=42.8
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 793123 0 7 0 3951 329 0 0 25 0 1 0 53357108 134062080 30389 1283457024 134512640 135121179 4288210320 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32730 30389 319 149 0 31921 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 133516

[startup+102.314 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 6973
/proc/meminfo: memFree=804764/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=131508 CPUtime=93.89
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 1704917 0 7 0 8663 726 0 0 25 0 1 0 53357108 134664192 30555 1283457024 134512640 135121179 4288210320 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32877 30555 321 149 0 32068 0
Current children cumulated CPU time (s) 101.92
Current children cumulated vsize (KiB) 134104

[startup+162.313 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 6979
/proc/meminfo: memFree=804516/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=130932 CPUtime=153.85
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 2758847 0 7 0 14221 1164 0 0 25 0 1 0 53357108 134074368 30505 1283457024 134512640 135121179 4288210320 18446744073709551615 4159968325 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32733 30505 321 149 0 31924 0
Current children cumulated CPU time (s) 161.88
Current children cumulated vsize (KiB) 133528

[startup+222.311 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 6982
/proc/meminfo: memFree=804532/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=131524 CPUtime=213.79
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 3798958 0 7 0 19758 1621 0 0 25 0 1 0 53357108 134680576 30598 1283457024 134512640 135121179 4288210320 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32881 30598 321 149 0 32072 0
Current children cumulated CPU time (s) 221.82
Current children cumulated vsize (KiB) 134120

[startup+282.312 s]
/proc/loadavg: 1.03 1.01 1.00 2/38 6982
/proc/meminfo: memFree=804416/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=134432 CPUtime=273.72
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 4812727 0 7 0 25305 2067 0 0 25 0 1 0 53357108 137658368 30709 1283457024 134512640 135121179 4288210320 18446744073709551615 134990531 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 33608 30709 321 149 0 32799 0
Current children cumulated CPU time (s) 281.75
Current children cumulated vsize (KiB) 137028



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.605 s]
/proc/loadavg: 1.03 1.01 1.00 2/38 6982
/proc/meminfo: memFree=804416/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=131896 CPUtime=282.01
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 4952167 0 7 0 26075 2126 0 0 25 0 1 0 53357108 135061504 30619 1283457024 134512640 135121179 4288210320 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32974 30619 321 149 0 32165 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 134492

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.605 s]
/proc/loadavg: 1.03 1.01 1.00 2/38 6982
/proc/meminfo: memFree=804416/1048576 swapFree=0/0
[pid=6960] ppid=6959 vsize=2596 CPUtime=8.03
/proc/6960/stat : 6960 (aspuncud-user-1) S 6959 6960 2160 34817 2160 4202496 572 63411 0 41 0 0 779 24 18 0 1 0 53357104 2658304 298 1283457024 134512640 135304128 4287546096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6960/statm: 649 298 251 194 0 36 0
[pid=6969] ppid=6960 vsize=131896 CPUtime=282.01
/proc/6969/stat : 6969 (unclasp) R 6960 6960 2160 34817 2160 4202496 4952167 0 7 0 26075 2126 0 0 25 0 1 0 53357108 135061504 30619 1283457024 134512640 135121179 4288210320 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6969/statm: 32974 30619 321 149 0 32165 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 134492

Child status: 0
Real time (s): 290.645
CPU time (s): 290.07
CPU user time (s): 268.549
CPU system time (s): 21.5213
CPU usage (%): 99.8023
Max. virtual memory (cumulated for all children) (KiB): 250300

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.549
system time used= 21.5213
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5018530
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= 9618
involuntary context switches= 11333

runsolver used 0 second user time and 0 second system time

The end