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/rand90.cudf.s-e-l-s-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand90.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand90.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.39 1.13 1.04 5/38 13152
/proc/meminfo: memFree=451084/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2584 CPUtime=0
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 2980749 2646016 279 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/13149/statm: 646 279 234 194 0 33 0
[pid=13150] ppid=13149 vsize=2584 CPUtime=0
/proc/13150/stat : 13150 (aspuncud-trendy) S 13149 13149 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 2980749 2646016 133 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/13150/statm: 646 133 87 194 0 33 0
[pid=13151] ppid=13150 vsize=2584 CPUtime=0
/proc/13151/stat : 13151 (aspuncud-trendy) R 13150 13149 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 2980749 2646016 150 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/13151/statm: 646 150 104 194 0 33 0
[pid=13152] ppid=13151 vsize=2584 CPUtime=0
/proc/13152/stat : 13152 (aspuncud-trendy) R 13151 13149 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2980749 2646016 46 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/13152/statm: 646 46 0 194 0 33 0

[startup+0.174688 s]
/proc/loadavg: 1.39 1.13 1.04 5/38 13152
/proc/meminfo: memFree=451084/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.214626 s]
/proc/loadavg: 1.39 1.13 1.04 5/38 13152
/proc/meminfo: memFree=451084/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.302709 s]
/proc/loadavg: 1.39 1.13 1.04 5/38 13152
/proc/meminfo: memFree=451084/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.715618 s]
/proc/loadavg: 1.39 1.13 1.04 5/38 13152
/proc/meminfo: memFree=451084/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.50279 s]
/proc/loadavg: 1.39 1.13 1.04 1/39 13163
/proc/meminfo: memFree=416048/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=3440 CPUtime=0
/proc/13161/stat : 13161 (unclasp) S 13149 13149 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 2980751 3522560 271 1283457024 134512640 135121179 4288379936 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13161/statm: 860 271 240 149 0 51 0
[pid=13162] ppid=13149 vsize=2696 CPUtime=0
/proc/13162/stat : 13162 (gringo) S 13149 13149 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 2980751 2760704 281 1283457024 134512640 137056543 4288881712 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13162/statm: 674 281 252 622 0 49 0
[pid=13163] ppid=13149 vsize=40664 CPUtime=1.22
/proc/13163/stat : 13163 (cudf2lp) R 13149 13149 1511 34817 1511 4202496 11538 0 0 0 117 5 0 0 25 0 1 0 2980751 41639936 8634 1283457024 134512640 135786343 4290166240 18446744073709551615 134625047 0 0 6 0 0 0 0 17 0 0 0 0
/proc/13163/statm: 10166 8634 126 311 0 9853 0
Current children cumulated CPU time (s) 1.23
Current children cumulated vsize (KiB) 49388

[startup+3.10794 s]
/proc/loadavg: 1.39 1.13 1.04 3/39 13163
/proc/meminfo: memFree=378880/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=0.01
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 2228 0 0 0 0 1 0 25 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=18040 CPUtime=0.06
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 4679 0 0 0 3 3 0 0 18 0 1 0 2980751 18472960 3885 1283457024 134512640 135121179 4288379936 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 4510 3885 275 149 0 3701 0
[pid=13162] ppid=13149 vsize=21784 CPUtime=0.8
/proc/13162/stat : 13162 (gringo) R 13149 13149 1511 34817 1511 4202496 6722 0 0 0 78 2 0 0 18 0 1 0 2980751 22306816 4455 1283457024 134512640 137056543 4288881712 18446744073709551615 134554148 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13162/statm: 5446 4455 253 622 0 4821 0
[pid=13163] ppid=13149 vsize=47332 CPUtime=1.91
/proc/13163/stat : 13163 (cudf2lp) R 13149 13149 1511 34817 1511 4202496 16193 0 0 0 185 6 0 0 25 0 1 0 2980751 48467968 11559 1283457024 134512640 135786343 4290166240 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/13163/statm: 11833 11559 137 311 0 11520 0
Current children cumulated CPU time (s) 2.78
Current children cumulated vsize (KiB) 89744

[startup+6.30883 s]
/proc/loadavg: 1.36 1.13 1.04 2/37 13164
/proc/meminfo: memFree=388336/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=46852 CPUtime=2.46
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 19184 0 0 0 236 10 0 0 21 0 1 0 2980751 47976448 10559 1283457024 134512640 135121179 4288379936 18446744073709551615 134878292 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11713 10559 328 149 0 10904 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 49440

[startup+12.7108 s]
/proc/loadavg: 1.33 1.13 1.04 2/37 13164
/proc/meminfo: memFree=388096/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=46852 CPUtime=8.85
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 95211 0 0 0 843 42 0 0 25 0 1 0 2980751 47976448 10565 1283457024 134512640 135121179 4288379936 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11713 10565 333 149 0 10904 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 49440

[startup+25.5056 s]
/proc/loadavg: 1.25 1.12 1.03 2/37 13166
/proc/meminfo: memFree=387476/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=47404 CPUtime=21.64
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 200523 0 0 0 2077 87 0 0 25 0 1 0 2980751 48541696 10683 1283457024 134512640 135121179 4288379936 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11851 10683 333 149 0 11042 0
Current children cumulated CPU time (s) 25.18
Current children cumulated vsize (KiB) 49992

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

[startup+25.6056 s]
/proc/loadavg: 1.25 1.12 1.03 2/37 13166
/proc/meminfo: memFree=387476/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=47404 CPUtime=21.74
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 201844 0 0 0 2086 88 0 0 25 0 1 0 2980751 48541696 10681 1283457024 134512640 135121179 4288379936 18446744073709551615 134734514 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11851 10681 333 149 0 11042 0
Current children cumulated CPU time (s) 25.28
Current children cumulated vsize (KiB) 49992

[startup+28.807 s]
/proc/loadavg: 1.25 1.12 1.03 2/37 13166
/proc/meminfo: memFree=387476/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=46852 CPUtime=24.93
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 238818 0 0 0 2389 104 0 0 25 0 1 0 2980751 47976448 10525 1283457024 134512640 135121179 4288379936 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11713 10525 333 149 0 10904 0
Current children cumulated CPU time (s) 28.47
Current children cumulated vsize (KiB) 49440

[startup+29.6074 s]
/proc/loadavg: 1.25 1.12 1.03 2/37 13166
/proc/meminfo: memFree=387476/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=46852 CPUtime=25.74
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 247973 0 0 0 2464 110 0 0 25 0 1 0 2980751 47976448 10525 1283457024 134512640 135121179 4288379936 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11713 10525 333 149 0 10904 0
Current children cumulated CPU time (s) 29.28
Current children cumulated vsize (KiB) 49440

[startup+30.0075 s]
/proc/loadavg: 1.23 1.12 1.03 2/37 13166
/proc/meminfo: memFree=388096/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=47816 CPUtime=26.14
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 252486 0 0 0 2504 110 0 0 25 0 1 0 2980751 48963584 10766 1283457024 134512640 135121179 4288379936 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11954 10766 333 149 0 11145 0
Current children cumulated CPU time (s) 29.68
Current children cumulated vsize (KiB) 50404

[startup+30.4077 s]
/proc/loadavg: 1.23 1.12 1.03 2/37 13166
/proc/meminfo: memFree=388096/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=3.54
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 622 32006 0 0 0 0 339 15 15 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
[pid=13161] ppid=13149 vsize=46852 CPUtime=26.54
/proc/13161/stat : 13161 (unclasp) R 13149 13149 1511 34817 1511 4202496 256816 0 0 0 2542 112 0 0 25 0 1 0 2980751 47976448 10569 1283457024 134512640 135121179 4288379936 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13161/statm: 11713 10569 333 149 0 10904 0
Current children cumulated CPU time (s) 30.08
Current children cumulated vsize (KiB) 49440

[startup+30.5077 s]
/proc/loadavg: 1.23 1.12 1.03 2/37 13166
/proc/meminfo: memFree=388096/1048576 swapFree=0/0
[pid=13149] ppid=13148 vsize=2588 CPUtime=30.18
/proc/13149/stat : 13149 (aspuncud-trendy) S 13148 13149 1511 34817 1511 4202496 676 289302 0 0 0 0 2890 128 19 0 1 0 2980749 2650112 297 1283457024 134512640 135304128 4294113616 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/13149/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 30.18
Current children cumulated vsize (KiB) 2588

Child status: 0
Real time (s): 30.5173
CPU time (s): 30.1979
CPU user time (s): 28.9098
CPU system time (s): 1.28808
CPU usage (%): 98.9532
Max. virtual memory (cumulated for all children) (KiB): 90728

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.9098
system time used= 1.28808
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 292460
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= 2157
involuntary context switches= 1914

runsolver used 0 second user time and 0 second system time

The end