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/aspuncud-trendy-1.3/rand314.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand314.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand314.cudf.s-e-l-s.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.06 1.03 1.00 1/35 5952
/proc/meminfo: memFree=765152/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=3020 CPUtime=0
/proc/5952/stat : 5952 (runsolver) D 5951 5952 1511 34817 1511 4202560 72 0 0 0 0 0 0 0 25 0 1 0 1452902 3092480 93 1283457024 134512640 134586868 4291731008 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/5952/statm: 755 93 62 19 0 54 0

[startup+0.20299 s]
/proc/loadavg: 1.06 1.03 1.00 1/35 5952
/proc/meminfo: memFree=765152/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306933 s]
/proc/loadavg: 1.06 1.03 1.00 1/35 5952
/proc/meminfo: memFree=765152/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.406942 s]
/proc/loadavg: 1.06 1.03 1.00 1/35 5952
/proc/meminfo: memFree=765152/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706962 s]
/proc/loadavg: 1.06 1.03 1.00 1/35 5952
/proc/meminfo: memFree=765152/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50702 s]
/proc/loadavg: 1.06 1.03 1.00 2/39 5966
/proc/meminfo: memFree=728724/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=3448 CPUtime=0
/proc/5964/stat : 5964 (unclasp) S 5952 5952 1511 34817 1511 4202496 402 0 6 0 0 0 0 0 24 0 1 0 1452906 3530752 272 1283457024 134512640 135121179 4290856064 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5964/statm: 862 272 240 149 0 53 0
[pid=5965] ppid=5952 vsize=2692 CPUtime=0.01
/proc/5965/stat : 5965 (gringo) S 5952 5952 1511 34817 1511 4202496 385 0 23 0 1 0 0 0 23 0 1 0 1452906 2756608 281 1283457024 134512640 137056543 4290858960 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5965/statm: 673 281 252 622 0 48 0
[pid=5966] ppid=5952 vsize=23464 CPUtime=1.02
/proc/5966/stat : 5966 (cudf2lp) R 5952 5952 1511 34817 1511 4202496 7070 0 16 0 101 1 0 0 25 0 1 0 1452906 24027136 5590 1283457024 134512640 135786343 4288250384 18446744073709551615 134566216 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5966/statm: 5866 5590 126 311 0 5553 0
Current children cumulated CPU time (s) 1.03
Current children cumulated vsize (KiB) 32200

[startup+3.10405 s]
/proc/loadavg: 1.06 1.03 1.00 2/39 5966
/proc/meminfo: memFree=692656/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=0
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 2225 0 3 0 0 0 0 25 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=16460 CPUtime=0.03
/proc/5964/stat : 5964 (unclasp) S 5952 5952 1511 34817 1511 4202496 4242 0 7 0 2 1 0 0 18 0 1 0 1452906 16855040 3455 1283457024 134512640 135121179 4290856064 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5964/statm: 4115 3455 275 149 0 3306 0
[pid=5965] ppid=5952 vsize=21036 CPUtime=0.59
/proc/5965/stat : 5965 (gringo) R 5952 5952 1511 34817 1511 4202496 6252 0 23 0 54 5 0 0 18 0 1 0 1452906 21540864 4008 1283457024 134512640 137056543 4290858960 18446744073709551615 136292941 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5965/statm: 5259 4008 253 622 0 4634 0
[pid=5966] ppid=5952 vsize=45412 CPUtime=1.97
/proc/5966/stat : 5966 (cudf2lp) R 5952 5952 1511 34817 1511 4202496 15672 0 16 0 194 3 0 0 25 0 1 0 1452906 46501888 11117 1283457024 134512640 135786343 4288250384 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5966/statm: 11353 11117 137 311 0 11040 0
Current children cumulated CPU time (s) 2.59
Current children cumulated vsize (KiB) 85504

[startup+6.30822 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 5966
/proc/meminfo: memFree=700200/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=46376 CPUtime=2.42
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 25290 0 8 0 233 9 0 0 21 0 1 0 1452906 47489024 10381 1283457024 134512640 135121179 4290856064 18446744073709551615 134990446 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11594 10381 328 149 0 10785 0
Current children cumulated CPU time (s) 5.79
Current children cumulated vsize (KiB) 48972

[startup+12.7104 s]
/proc/loadavg: 1.05 1.03 1.00 2/37 5967
/proc/meminfo: memFree=700820/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=44568 CPUtime=8.82
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 86237 0 8 0 857 25 0 0 25 0 1 0 1452906 45637632 10011 1283457024 134512640 135121179 4290856064 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11142 10011 333 149 0 10333 0
Current children cumulated CPU time (s) 12.19
Current children cumulated vsize (KiB) 47164

[startup+25.5144 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=699952/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=46412 CPUtime=21.61
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 199716 0 8 0 2070 91 0 0 25 0 1 0 1452906 47525888 10432 1283457024 134512640 135121179 4290856064 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11603 10432 333 149 0 10794 0
Current children cumulated CPU time (s) 24.98
Current children cumulated vsize (KiB) 49008

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

[startup+25.7144 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=699952/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=45488 CPUtime=21.81
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 201879 0 8 0 2090 91 0 0 25 0 1 0 1452906 46579712 10201 1283457024 134512640 135121179 4290856064 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11372 10201 333 149 0 10563 0
Current children cumulated CPU time (s) 25.18
Current children cumulated vsize (KiB) 48084

[startup+26.5047 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=699084/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=46408 CPUtime=22.6
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 206029 0 8 0 2168 92 0 0 25 0 1 0 1452906 47521792 10436 1283457024 134512640 135121179 4290856064 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11602 10436 333 149 0 10793 0
Current children cumulated CPU time (s) 25.97
Current children cumulated vsize (KiB) 49004

[startup+27.305 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=699084/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=45492 CPUtime=23.4
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 210874 0 8 0 2248 92 0 0 25 0 1 0 1452906 46583808 10243 1283457024 134512640 135121179 4290856064 18446744073709551615 134713298 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11373 10243 333 149 0 10564 0
Current children cumulated CPU time (s) 26.77
Current children cumulated vsize (KiB) 48088

[startup+27.7052 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=700696/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=45896 CPUtime=23.8
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 215167 0 8 0 2287 93 0 0 25 0 1 0 1452906 46997504 10312 1283457024 134512640 135121179 4290856064 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11474 10312 333 149 0 10665 0
Current children cumulated CPU time (s) 27.17
Current children cumulated vsize (KiB) 48492

[startup+27.8052 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 5968
/proc/meminfo: memFree=700696/1048576 swapFree=0/0
[pid=5952] ppid=5951 vsize=2596 CPUtime=3.37
/proc/5952/stat : 5952 (aspuncud-trendy) S 5951 5952 1511 34817 1511 4202496 624 31150 0 42 0 0 327 10 15 0 1 0 1452902 2658304 298 1283457024 134512640 135304128 4291425984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5952/statm: 649 298 251 194 0 36 0
[pid=5964] ppid=5952 vsize=45540 CPUtime=23.9
/proc/5964/stat : 5964 (unclasp) R 5952 5952 1511 34817 1511 4202496 215509 0 8 0 2297 93 0 0 25 0 1 0 1452906 46632960 10312 1283457024 134512640 135121179 4290856064 18446744073709551615 4157761708 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5964/statm: 11385 10312 342 149 0 10576 0
Current children cumulated CPU time (s) 27.27
Current children cumulated vsize (KiB) 48136

Child status: 0
Real time (s): 27.8493
CPU time (s): 27.3057
CPU user time (s): 26.2496
CPU system time (s): 1.05607
CPU usage (%): 98.0482
Max. virtual memory (cumulated for all children) (KiB): 87900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 26.2496
system time used= 1.05607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 249834
page faults= 52
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2134
involuntary context switches= 1825

runsolver used 0 second user time and 0.004 second system time

The end