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/rand438.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand438.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand438.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.12 1.06 1.01 5/38 20043
/proc/meminfo: memFree=482728/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2584 CPUtime=0
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 4587753 2646016 279 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/20040/statm: 646 279 234 194 0 33 0
[pid=20041] ppid=20040 vsize=2584 CPUtime=0
/proc/20041/stat : 20041 (aspcud-trendy-1) S 20040 20040 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 4587754 2646016 133 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/20041/statm: 646 133 87 194 0 33 0
[pid=20042] ppid=20041 vsize=2584 CPUtime=0
/proc/20042/stat : 20042 (aspcud-trendy-1) R 20041 20040 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 4587754 2646016 150 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/20042/statm: 646 150 104 194 0 33 0
[pid=20043] ppid=20042 vsize=2584 CPUtime=0
/proc/20043/stat : 20043 (aspcud-trendy-1) R 20042 20040 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4587754 2646016 46 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/20043/statm: 646 46 0 194 0 33 0

[startup+0.159869 s]
/proc/loadavg: 1.12 1.06 1.01 5/38 20043
/proc/meminfo: memFree=482728/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=0.01
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 616 2231 0 0 0 0 0 1 25 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.209869 s]
/proc/loadavg: 1.12 1.06 1.01 5/38 20043
/proc/meminfo: memFree=482728/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=0.01
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 616 2231 0 0 0 0 0 1 25 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.309888 s]
/proc/loadavg: 1.12 1.06 1.01 5/38 20043
/proc/meminfo: memFree=482728/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=0.01
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 616 2231 0 0 0 0 0 1 25 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.709956 s]
/proc/loadavg: 1.12 1.06 1.01 5/38 20043
/proc/meminfo: memFree=482728/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=0.01
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 616 2231 0 0 0 0 0 1 25 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.51011 s]
/proc/loadavg: 1.11 1.06 1.01 2/39 20054
/proc/meminfo: memFree=458032/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=0.01
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 616 2231 0 0 0 0 0 1 25 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
[pid=20052] ppid=20040 vsize=1924 CPUtime=0
/proc/20052/stat : 20052 (clasp) S 20040 20040 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 4587755 1970176 159 1283457024 134512640 136285277 4286663168 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/20052/statm: 481 159 144 433 0 46 0
[pid=20053] ppid=20040 vsize=2584 CPUtime=0
/proc/20053/stat : 20053 (gringo) S 20040 20040 1511 34817 1511 4202496 403 0 0 0 0 0 0 0 25 0 1 0 4587755 2646016 271 1283457024 134512640 136933539 4290301424 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/20053/statm: 646 271 242 592 0 51 0
[pid=20054] ppid=20040 vsize=25520 CPUtime=1.49
/proc/20054/stat : 20054 (cudf2lp) R 20040 20040 1511 34817 1511 4202496 7594 0 0 0 145 4 0 0 25 0 1 0 4587755 26132480 5745 1283457024 134512640 135786343 4292106176 18446744073709551615 134690192 0 0 6 0 0 0 0 17 0 0 0 0
/proc/20054/statm: 6380 5745 126 311 0 6067 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 32620

[startup+3.11041 s]
/proc/loadavg: 1.11 1.06 1.01 2/39 20054
/proc/meminfo: memFree=441664/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=2.43
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 617 15600 0 0 0 0 233 10 18 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
[pid=20052] ppid=20040 vsize=15992 CPUtime=0.06
/proc/20052/stat : 20052 (clasp) R 20040 20040 1511 34817 1511 4202496 4295 0 0 0 5 1 0 0 18 0 1 0 4587755 16375808 3641 1283457024 134512640 136285277 4286663168 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20052/statm: 3998 3641 177 433 0 3563 0
[pid=20053] ppid=20040 vsize=25300 CPUtime=0.6
/proc/20053/stat : 20053 (gringo) R 20040 20040 1511 34817 1511 4202496 6655 0 0 0 59 1 0 0 18 0 1 0 4587755 25907200 4976 1283457024 134512640 136933539 4290301424 18446744073709551615 134691756 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/20053/statm: 6325 4976 253 592 0 5730 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 43884

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

[startup+3.21042 s]
/proc/loadavg: 1.11 1.06 1.01 2/39 20054
/proc/meminfo: memFree=441664/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=2.43
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 617 15600 0 0 0 0 233 10 18 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
[pid=20052] ppid=20040 vsize=17048 CPUtime=0.07
/proc/20052/stat : 20052 (clasp) R 20040 20040 1511 34817 1511 4202496 4581 0 0 0 6 1 0 0 18 0 1 0 4587755 17457152 3927 1283457024 134512640 136285277 4286663168 18446744073709551615 134871651 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20052/statm: 4262 3927 177 433 0 3827 0
[pid=20053] ppid=20040 vsize=27900 CPUtime=0.69
/proc/20053/stat : 20053 (gringo) R 20040 20040 1511 34817 1511 4202496 7257 0 0 0 68 1 0 0 18 0 1 0 4587755 28569600 5578 1283457024 134512640 136933539 4290301424 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/20053/statm: 6975 5578 253 592 0 6380 0
Current children cumulated CPU time (s) 3.19
Current children cumulated vsize (KiB) 47540

[startup+4.81064 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 20054
/proc/meminfo: memFree=458560/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=3.2
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 617 23923 0 0 0 0 309 11 15 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
[pid=20052] ppid=20040 vsize=25616 CPUtime=1.59
/proc/20052/stat : 20052 (clasp) R 20040 20040 1511 34817 1511 4202496 7252 0 0 0 155 4 0 0 19 0 1 0 4587755 26230784 6146 1283457024 134512640 136285277 4286663168 18446744073709551615 134930818 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20052/statm: 6404 6146 234 433 0 5969 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 28208

[startup+5.2107 s]
/proc/loadavg: 1.11 1.06 1.01 2/37 20054
/proc/meminfo: memFree=458560/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2592 CPUtime=3.2
/proc/20040/stat : 20040 (aspcud-trendy-1) S 20039 20040 1511 34817 1511 4202496 617 23923 0 0 0 0 309 11 15 0 1 0 4587753 2654208 298 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20040/statm: 648 298 251 194 0 35 0
[pid=20052] ppid=20040 vsize=25616 CPUtime=1.99
/proc/20052/stat : 20052 (clasp) R 20040 20040 1511 34817 1511 4202496 7262 0 0 0 195 4 0 0 20 0 1 0 4587755 26230784 6156 1283457024 134512640 136285277 4286663168 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20052/statm: 6404 6156 234 433 0 5969 0
Current children cumulated CPU time (s) 5.19
Current children cumulated vsize (KiB) 28208

[startup+5.61073 s]
/proc/loadavg: 1.10 1.06 1.01 2/37 20054
/proc/meminfo: memFree=458560/1048576 swapFree=0/0
[pid=20040] ppid=20039 vsize=2660 CPUtime=5.59
/proc/20040/stat : 20040 (aspcud-trendy-1) R 20039 20040 1511 34817 1511 4202496 923 33878 0 0 0 0 542 17 19 0 1 0 4587753 2723840 317 1283457024 134512640 135304128 4292427712 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/20040/statm: 665 317 256 194 0 52 0
Current children cumulated CPU time (s) 5.59
Current children cumulated vsize (KiB) 2660

Child status: 0
Real time (s): 5.6133
CPU time (s): 5.60835
CPU user time (s): 5.42434
CPU system time (s): 0.184011
CPU usage (%): 99.9118
Max. virtual memory (cumulated for all children) (KiB): 62660

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.42434
system time used= 0.184011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35426
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= 915
involuntary context switches= 699

runsolver used 0.008 second user time and 0 second system time

The end