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/rand512.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand512.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand512.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.01 1.02 1.00 1/36 7463
/proc/meminfo: memFree=944788/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=3020 CPUtime=0
/proc/7463/stat : 7463 (runsolver) D 7462 7463 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 53643821 3092480 94 1283457024 134512640 134586868 4294523104 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/7463/statm: 755 94 62 19 0 54 0

[startup+0.204486 s]
/proc/loadavg: 1.01 1.02 1.00 1/36 7463
/proc/meminfo: memFree=944788/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.304875 s]
/proc/loadavg: 1.01 1.02 1.00 1/36 7463
/proc/meminfo: memFree=944788/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.404896 s]
/proc/loadavg: 1.01 1.02 1.00 1/36 7463
/proc/meminfo: memFree=944788/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.704966 s]
/proc/loadavg: 1.01 1.02 1.00 1/36 7463
/proc/meminfo: memFree=944788/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50516 s]
/proc/loadavg: 1.09 1.04 1.01 2/40 7474
/proc/meminfo: memFree=925308/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=3444 CPUtime=0
/proc/7472/stat : 7472 (unclasp) D 7463 7463 2160 34817 2160 4202496 407 0 5 0 0 0 0 0 18 0 1 0 53643826 3526656 277 1283457024 134512640 135121179 4286757232 18446744073709551615 134679216 0 0 6 16384 18446744071564332000 0 0 17 0 0 0 0
/proc/7472/statm: 861 277 244 149 0 52 0
[pid=7473] ppid=7463 vsize=2992 CPUtime=0
/proc/7473/stat : 7473 (gringo) S 7463 7463 2160 34817 2160 4202496 440 0 23 0 0 0 0 0 18 0 1 0 53643826 3063808 336 1283457024 134512640 137056543 4288880400 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7473/statm: 748 336 253 622 0 123 0
[pid=7474] ppid=7463 vsize=26528 CPUtime=1.26
/proc/7474/stat : 7474 (cudf2lp) R 7463 7463 2160 34817 2160 4202496 8639 0 15 0 120 6 0 0 25 0 1 0 53643826 27164672 6415 1283457024 134512640 135786343 4286756848 18446744073709551615 134571667 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7474/statm: 6632 6415 139 311 0 6319 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 35556

[startup+3.10554 s]
/proc/loadavg: 1.09 1.04 1.01 3/40 7474
/proc/meminfo: memFree=889348/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=0
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 1519 0 3 0 0 0 0 25 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=25860 CPUtime=0.16
/proc/7472/stat : 7472 (unclasp) S 7463 7463 2160 34817 2160 4202496 6994 0 6 0 15 1 0 0 18 0 1 0 53643826 26480640 5801 1283457024 134512640 135121179 4286757232 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7472/statm: 6465 5801 275 149 0 5656 0
[pid=7473] ppid=7463 vsize=36416 CPUtime=1.26
/proc/7473/stat : 7473 (gringo) R 7463 7463 2160 34817 2160 4202496 11208 0 23 0 124 2 0 0 18 0 1 0 53643826 37289984 7074 1283457024 134512640 137056543 4288880400 18446744073709551615 134547870 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7473/statm: 9104 7074 253 622 0 8479 0
[pid=7474] ppid=7463 vsize=26528 CPUtime=1.42
/proc/7474/stat : 7474 (cudf2lp) R 7463 7463 2160 34817 2160 4202496 8639 0 15 0 136 6 0 0 25 0 1 0 53643826 27164672 6415 1283457024 134512640 135786343 4286756848 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7474/statm: 6632 6415 139 311 0 6319 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 91396

[startup+6.30653 s]
/proc/loadavg: 1.08 1.04 1.00 2/38 7474
/proc/meminfo: memFree=878904/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=66832 CPUtime=1.98
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 30937 0 7 0 184 14 0 0 20 0 1 0 53643826 68435968 15311 1283457024 134512640 135121179 4286757232 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16708 15311 319 149 0 15899 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 69424

[startup+12.709 s]
/proc/loadavg: 1.08 1.04 1.00 2/38 7474
/proc/meminfo: memFree=880640/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=65824 CPUtime=8.38
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 116338 0 7 0 792 46 0 0 25 0 1 0 53643826 67403776 15062 1283457024 134512640 135121179 4286757232 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16456 15062 319 149 0 15647 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 68416

[startup+25.5038 s]
/proc/loadavg: 1.06 1.03 1.00 2/38 7474
/proc/meminfo: memFree=880888/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=67888 CPUtime=21.17
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 289515 0 7 0 2008 109 0 0 25 0 1 0 53643826 69517312 15589 1283457024 134512640 135121179 4286757232 18446744073709551615 4157713174 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16972 15589 321 149 0 16163 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 70480

[startup+51.1124 s]
/proc/loadavg: 1.04 1.03 1.00 2/40 7477
/proc/meminfo: memFree=878756/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=67380 CPUtime=46.75
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 595125 0 7 0 4427 248 0 0 25 0 1 0 53643826 68997120 15530 1283457024 134512640 135121179 4286757232 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16845 15530 321 149 0 16036 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 69972

[startup+102.312 s]
/proc/loadavg: 1.02 1.02 1.00 2/40 7482
/proc/meminfo: memFree=879996/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=66352 CPUtime=97.89
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 1150389 0 7 0 9295 494 0 0 25 0 1 0 53643826 67944448 15298 1283457024 134512640 135121179 4286757232 18446744073709551615 134878464 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16588 15298 321 149 0 15779 0
Current children cumulated CPU time (s) 101.95
Current children cumulated vsize (KiB) 68944

[startup+162.313 s]
/proc/loadavg: 1.00 1.02 1.00 2/39 7485
/proc/meminfo: memFree=879268/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=66360 CPUtime=157.83
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 1772768 0 7 0 15016 767 0 0 25 0 1 0 53643826 67952640 15329 1283457024 134512640 135121179 4286757232 18446744073709551615 134734473 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16590 15329 321 149 0 15781 0
Current children cumulated CPU time (s) 161.89
Current children cumulated vsize (KiB) 68952

[startup+222.314 s]
/proc/loadavg: 1.00 1.01 1.00 2/38 7485
/proc/meminfo: memFree=879152/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=66392 CPUtime=217.79
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 2496759 0 7 0 20699 1080 0 0 25 0 1 0 53643826 67985408 15317 1283457024 134512640 135121179 4286757232 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16598 15317 321 149 0 15789 0
Current children cumulated CPU time (s) 221.85
Current children cumulated vsize (KiB) 68984

[startup+282.314 s]
/proc/loadavg: 1.00 1.01 1.00 2/38 7485
/proc/meminfo: memFree=878036/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=67916 CPUtime=277.7
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 3279378 0 7 0 26336 1434 0 0 25 0 1 0 53643826 69545984 15717 1283457024 134512640 135121179 4286757232 18446744073709551615 134981874 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16979 15717 321 149 0 16170 0
Current children cumulated CPU time (s) 281.76
Current children cumulated vsize (KiB) 70508



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.608 s]
/proc/loadavg: 1.00 1.00 1.00 2/38 7485
/proc/meminfo: memFree=878408/1048576 swapFree=0/0
[pid=7463] ppid=7462 vsize=2592 CPUtime=4.06
/proc/7463/stat : 7463 (aspuncud-user-1) S 7462 7463 2160 34817 2160 4202496 575 37578 0 41 0 0 393 13 18 0 1 0 53643821 2654208 298 1283457024 134512640 135304128 4294668736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7463/statm: 648 298 251 194 0 35 0
[pid=7472] ppid=7463 vsize=66900 CPUtime=285.99
/proc/7472/stat : 7472 (unclasp) R 7463 7463 2160 34817 2160 4202496 3385667 0 7 0 27112 1487 0 0 25 0 1 0 53643826 68505600 15468 1283457024 134512640 135121179 4286757232 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7472/statm: 16725 15468 321 149 0 15916 0
Current children cumulated CPU time (s) 290.05
Current children cumulated vsize (KiB) 69492

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.649
CPU time (s): 290.074
CPU user time (s): 275.053
CPU system time (s): 15.0209
CPU usage (%): 99.8023
Max. virtual memory (cumulated for all children) (KiB): 149976

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 275.053
system time used= 15.0209
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 3426198
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= 4308
involuntary context switches= 6863

runsolver used 0 second user time and 0 second system time

The end