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/201108241238/aspcud-trendy-1.5/rand172.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand172.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand172.cudf.user-upgrades.result 

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 5/36 6991
/proc/meminfo: memFree=654388/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2588 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 1745326 2650112 279 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/6989/statm: 647 279 234 194 0 34 0
[pid=6990] ppid=6989 vsize=2588 CPUtime=0
/proc/6990/stat : 6990 (aspcud-trendy-1) R 6989 6989 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1745327 2650112 132 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6990/statm: 647 132 86 194 0 34 0
[pid=6991] ppid=6990 vsize=2588 CPUtime=0
/proc/6991/stat : 6991 (aspcud-trendy-1) R 6990 6989 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1745327 2650112 46 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6991/statm: 647 46 0 194 0 34 0

[startup+0.145439 s]
/proc/loadavg: 1.01 1.02 1.00 5/36 6991
/proc/meminfo: memFree=654388/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 617 2231 0 0 0 0 0 0 25 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205443 s]
/proc/loadavg: 1.01 1.02 1.00 5/36 6991
/proc/meminfo: memFree=654388/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 617 2231 0 0 0 0 0 0 25 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305457 s]
/proc/loadavg: 1.01 1.02 1.00 5/36 6991
/proc/meminfo: memFree=654388/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 617 2231 0 0 0 0 0 0 25 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.70551 s]
/proc/loadavg: 1.01 1.02 1.00 5/36 6991
/proc/meminfo: memFree=654388/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 617 2231 0 0 0 0 0 0 25 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50561 s]
/proc/loadavg: 1.01 1.02 1.00 2/38 7003
/proc/meminfo: memFree=629428/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=0
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 617 2231 0 0 0 0 0 0 25 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=1924 CPUtime=0
/proc/7001/stat : 7001 (clasp) S 6989 6989 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 1745328 1970176 159 1283457024 134512640 136285277 4288527296 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7001/statm: 481 159 144 433 0 46 0
[pid=7002] ppid=6989 vsize=2588 CPUtime=0
/proc/7002/stat : 7002 (gringo) S 6989 6989 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 1745328 2650112 272 1283457024 134512640 136933539 4288322576 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7002/statm: 647 272 242 592 0 52 0
[pid=7003] ppid=6989 vsize=25520 CPUtime=1.49
/proc/7003/stat : 7003 (cudf2lp) R 6989 6989 1511 34817 1511 4202496 7590 0 0 0 145 4 0 0 25 0 1 0 1745328 26132480 5741 1283457024 134512640 135786343 4286778032 18446744073709551615 134605776 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7003/statm: 6380 5741 126 311 0 6067 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 32628

[startup+3.10579 s]
/proc/loadavg: 1.01 1.02 1.00 2/38 7003
/proc/meminfo: memFree=608472/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=2.44
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 618 15599 0 0 0 0 238 6 18 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=15992 CPUtime=0.1
/proc/7001/stat : 7001 (clasp) R 6989 6989 1511 34817 1511 4202496 4302 0 0 0 10 0 0 0 18 0 1 0 1745328 16375808 3648 1283457024 134512640 136285277 4288527296 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7001/statm: 3998 3648 177 433 0 3563 0
[pid=7002] ppid=6989 vsize=25300 CPUtime=0.55
/proc/7002/stat : 7002 (gringo) R 6989 6989 1511 34817 1511 4202496 6654 0 0 0 53 2 0 0 18 0 1 0 1745328 25907200 4975 1283457024 134512640 136933539 4288322576 18446744073709551615 136158869 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7002/statm: 6325 4975 253 592 0 5730 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 43888

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

[startup+3.20582 s]
/proc/loadavg: 1.01 1.02 1.00 2/38 7003
/proc/meminfo: memFree=608472/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=2.44
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 618 15599 0 0 0 0 238 6 18 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=17180 CPUtime=0.15
/proc/7001/stat : 7001 (clasp) R 6989 6989 1511 34817 1511 4202496 4603 0 0 0 15 0 0 0 18 0 1 0 1745328 17592320 3949 1283457024 134512640 136285277 4288527296 18446744073709551615 134799108 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7001/statm: 4295 3949 177 433 0 3860 0
[pid=7002] ppid=6989 vsize=27896 CPUtime=0.6
/proc/7002/stat : 7002 (gringo) R 6989 6989 1511 34817 1511 4202496 7274 0 0 0 57 3 0 0 18 0 1 0 1745328 28565504 5595 1283457024 134512640 136933539 4288322576 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7002/statm: 6974 5595 253 592 0 6379 0
Current children cumulated CPU time (s) 3.19
Current children cumulated vsize (KiB) 47672

[startup+4.00609 s]
/proc/loadavg: 1.09 1.04 1.01 3/37 7003
/proc/meminfo: memFree=613944/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=3.13
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 618 23923 0 0 0 0 302 11 15 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=25624 CPUtime=0.86
/proc/7001/stat : 7001 (clasp) R 6989 6989 1511 34817 1511 4202496 7252 0 0 0 86 0 0 0 18 0 1 0 1745328 26238976 6146 1283457024 134512640 136285277 4288527296 18446744073709551615 134959927 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7001/statm: 6406 6146 234 433 0 5971 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 28220

[startup+4.4062 s]
/proc/loadavg: 1.09 1.04 1.01 2/36 7003
/proc/meminfo: memFree=629956/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=3.13
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 618 23923 0 0 0 0 302 11 15 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=25624 CPUtime=1.26
/proc/7001/stat : 7001 (clasp) R 6989 6989 1511 34817 1511 4202496 7252 0 0 0 126 0 0 0 19 0 1 0 1745328 26238976 6146 1283457024 134512640 136285277 4288527296 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7001/statm: 6406 6146 234 433 0 5971 0
Current children cumulated CPU time (s) 4.39
Current children cumulated vsize (KiB) 28220

[startup+4.60626 s]
/proc/loadavg: 1.09 1.04 1.01 2/36 7003
/proc/meminfo: memFree=629956/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2596 CPUtime=3.13
/proc/6989/stat : 6989 (aspcud-trendy-1) S 6988 6989 1511 34817 1511 4202496 618 23923 0 0 0 0 302 11 15 0 1 0 1745326 2658304 298 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6989/statm: 649 298 251 194 0 36 0
[pid=7001] ppid=6989 vsize=25624 CPUtime=1.46
/proc/7001/stat : 7001 (clasp) R 6989 6989 1511 34817 1511 4202496 7252 0 0 0 146 0 0 0 19 0 1 0 1745328 26238976 6146 1283457024 134512640 136285277 4288527296 18446744073709551615 134931317 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7001/statm: 6406 6146 234 433 0 5971 0
Current children cumulated CPU time (s) 4.59
Current children cumulated vsize (KiB) 28220

[startup+4.70629 s]
/proc/loadavg: 1.09 1.04 1.01 2/36 7003
/proc/meminfo: memFree=629956/1048576 swapFree=0/0
[pid=6989] ppid=6988 vsize=2696 CPUtime=4.7
/proc/6989/stat : 6989 (aspcud-trendy-1) R 6988 6989 1511 34817 1511 4202496 854 32998 0 0 0 0 458 12 19 0 1 0 1745326 2760704 322 1283457024 134512640 135304128 4291473104 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/6989/statm: 674 322 256 194 0 61 0
Current children cumulated CPU time (s) 4.7
Current children cumulated vsize (KiB) 2696

Child status: 0
Real time (s): 4.71317
CPU time (s): 4.70829
CPU user time (s): 4.58829
CPU system time (s): 0.120007
CPU usage (%): 99.8966
Max. virtual memory (cumulated for all children) (KiB): 62664

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.58829
system time used= 0.120007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35419
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= 913
involuntary context switches= 688

runsolver used 0 second user time and 0 second system time

The end