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/rand496.cudf.s-e-l-s-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand496.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand496.cudf.s-e-l-s-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.30 1.14 1.04 3/35 7565
/proc/meminfo: memFree=601540/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2592 CPUtime=0
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 25 0 1 0 1769995 2654208 280 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/7563/statm: 648 280 234 194 0 35 0
[pid=7564] ppid=7563 vsize=2592 CPUtime=0
/proc/7564/stat : 7564 (aspuncud-trendy) R 7563 7563 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1769995 2654208 133 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7564/statm: 648 133 86 194 0 35 0
[pid=7565] ppid=7564 vsize=2592 CPUtime=0
/proc/7565/stat : 7565 (aspuncud-trendy) R 7564 7563 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1769995 2654208 47 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7565/statm: 648 47 0 194 0 35 0

[startup+0.199771 s]
/proc/loadavg: 1.30 1.14 1.04 3/35 7565
/proc/meminfo: memFree=601540/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.211865 s]
/proc/loadavg: 1.30 1.14 1.04 3/35 7565
/proc/meminfo: memFree=601540/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.317652 s]
/proc/loadavg: 1.30 1.14 1.04 3/35 7565
/proc/meminfo: memFree=601540/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.707691 s]
/proc/loadavg: 1.30 1.14 1.04 3/35 7565
/proc/meminfo: memFree=601540/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50773 s]
/proc/loadavg: 1.30 1.14 1.04 2/37 7577
/proc/meminfo: memFree=566052/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=3440 CPUtime=0
/proc/7575/stat : 7575 (unclasp) S 7563 7563 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1769996 3522560 271 1283457024 134512640 135121179 4292722752 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7575/statm: 860 271 240 149 0 51 0
[pid=7576] ppid=7563 vsize=2692 CPUtime=0
/proc/7576/stat : 7576 (gringo) S 7563 7563 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1769996 2756608 281 1283457024 134512640 137056543 4293165120 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7576/statm: 673 281 252 622 0 48 0
[pid=7577] ppid=7563 vsize=40660 CPUtime=1.26
/proc/7577/stat : 7577 (cudf2lp) R 7563 7563 1511 34817 1511 4202496 11582 0 0 0 121 5 0 0 25 0 1 0 1769996 41635840 8677 1283457024 134512640 135786343 4289736048 18446744073709551615 135044416 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7577/statm: 10165 8677 126 311 0 9852 0
Current children cumulated CPU time (s) 1.27
Current children cumulated vsize (KiB) 49388

[startup+3.1121 s]
/proc/loadavg: 1.27 1.14 1.04 3/37 7577
/proc/meminfo: memFree=527828/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=0.01
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 2225 0 0 0 0 0 1 25 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=18828 CPUtime=0.08
/proc/7575/stat : 7575 (unclasp) S 7563 7563 1511 34817 1511 4202496 4897 0 0 0 8 0 0 0 18 0 1 0 1769996 19279872 4103 1283457024 134512640 135121179 4292722752 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7575/statm: 4707 4103 275 149 0 3898 0
[pid=7576] ppid=7563 vsize=22272 CPUtime=0.78
/proc/7576/stat : 7576 (gringo) R 7563 7563 1511 34817 1511 4202496 6937 0 0 0 73 5 0 0 18 0 1 0 1769996 22806528 4670 1283457024 134512640 137056543 4293165120 18446744073709551615 134554221 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7576/statm: 5568 4670 253 622 0 4943 0
[pid=7577] ppid=7563 vsize=47328 CPUtime=1.97
/proc/7577/stat : 7577 (cudf2lp) R 7563 7563 1511 34817 1511 4202496 16194 0 0 0 192 5 0 0 25 0 1 0 1769996 48463872 11559 1283457024 134512640 135786343 4289736048 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7577/statm: 11832 11559 137 311 0 11519 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 91024

[startup+6.31271 s]
/proc/loadavg: 1.27 1.14 1.04 2/35 7577
/proc/meminfo: memFree=538896/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=47364 CPUtime=2.54
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 24973 0 0 0 244 10 0 0 22 0 1 0 1769996 48500736 10666 1283457024 134512640 135121179 4292722752 18446744073709551615 134849051 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 11841 10666 328 149 0 11032 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 49960

[startup+12.7052 s]
/proc/loadavg: 1.23 1.14 1.04 2/37 7579
/proc/meminfo: memFree=537640/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=49000 CPUtime=8.93
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 104472 0 0 0 847 46 0 0 25 0 1 0 1769996 50176000 10951 1283457024 134512640 135121179 4292722752 18446744073709551615 4157831958 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 12250 10951 333 149 0 11441 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 51596

[startup+25.5099 s]
/proc/loadavg: 1.20 1.13 1.04 2/37 7580
/proc/meminfo: memFree=537020/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=47672 CPUtime=21.72
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 197321 0 0 0 2097 75 0 0 25 0 1 0 1769996 48816128 10781 1283457024 134512640 135121179 4292722752 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 11918 10781 333 149 0 11109 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 50268

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

[startup+25.61 s]
/proc/loadavg: 1.20 1.13 1.04 2/37 7580
/proc/meminfo: memFree=537020/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=48648 CPUtime=21.82
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 198648 0 0 0 2107 75 0 0 25 0 1 0 1769996 49815552 11025 1283457024 134512640 135121179 4292722752 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 12162 11025 333 149 0 11353 0
Current children cumulated CPU time (s) 25.33
Current children cumulated vsize (KiB) 51244

[startup+28.811 s]
/proc/loadavg: 1.18 1.13 1.04 2/37 7581
/proc/meminfo: memFree=536400/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=48996 CPUtime=25.02
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 226722 0 0 0 2414 88 0 0 25 0 1 0 1769996 50171904 11080 1283457024 134512640 135121179 4292722752 18446744073709551615 134713294 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 12249 11080 333 149 0 11440 0
Current children cumulated CPU time (s) 28.53
Current children cumulated vsize (KiB) 51592

[startup+30.4116 s]
/proc/loadavg: 1.18 1.13 1.04 2/37 7581
/proc/meminfo: memFree=537020/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=48636 CPUtime=26.61
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 240982 0 0 0 2568 93 0 0 25 0 1 0 1769996 49803264 10988 1283457024 134512640 135121179 4292722752 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 12159 10988 333 149 0 11350 0
Current children cumulated CPU time (s) 30.12
Current children cumulated vsize (KiB) 51232

[startup+30.8117 s]
/proc/loadavg: 1.18 1.13 1.04 2/37 7581
/proc/meminfo: memFree=536276/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=48636 CPUtime=27.01
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 244104 0 0 0 2607 94 0 0 25 0 1 0 1769996 49803264 10991 1283457024 134512640 135121179 4292722752 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 12159 10991 333 149 0 11350 0
Current children cumulated CPU time (s) 30.52
Current children cumulated vsize (KiB) 51232

[startup+31.0117 s]
/proc/loadavg: 1.18 1.13 1.04 2/37 7581
/proc/meminfo: memFree=536276/1048576 swapFree=0/0
[pid=7563] ppid=7562 vsize=2596 CPUtime=3.51
/proc/7563/stat : 7563 (aspuncud-trendy) S 7562 7563 1511 34817 1511 4202496 624 32117 0 0 0 0 335 16 15 0 1 0 1769995 2658304 298 1283457024 134512640 135304128 4290041184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7563/statm: 649 298 251 194 0 36 0
[pid=7575] ppid=7563 vsize=46456 CPUtime=27.21
/proc/7575/stat : 7575 (unclasp) R 7563 7563 1511 34817 1511 4202496 244942 0 0 0 2627 94 0 0 25 0 1 0 1769996 47570944 10547 1283457024 134512640 135121179 4292722752 18446744073709551615 4157793693 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7575/statm: 11614 10547 342 149 0 10805 0
Current children cumulated CPU time (s) 30.72
Current children cumulated vsize (KiB) 49052

Child status: 0
Real time (s): 31.0623
CPU time (s): 30.7979
CPU user time (s): 29.6739
CPU system time (s): 1.12407
CPU usage (%): 99.1488
Max. virtual memory (cumulated for all children) (KiB): 91380

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 29.6739
system time used= 1.12407
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 280230
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= 2187
involuntary context switches= 1956

runsolver used 0 second user time and 0 second system time

The end