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/rand439.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand439.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand439.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.00 1.03 1.00 5/34 11539
/proc/meminfo: memFree=562992/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2588 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 25 0 1 0 2682604 2650112 279 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/11538/statm: 647 279 234 194 0 34 0
[pid=11539] ppid=11538 vsize=2588 CPUtime=0
/proc/11539/stat : 11539 (aspuncud-trendy) R 11538 11538 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2682604 2650112 132 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11539/statm: 647 132 86 194 0 34 0
[pid=11540] ppid=11539 vsize=2588 CPUtime=0
/proc/11540/stat : 11540 (aspuncud-trendy) R 11539 11538 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2682604 2650112 46 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11540/statm: 647 46 0 194 0 34 0

[startup+0.178784 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 11539
/proc/meminfo: memFree=562992/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 25 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.206796 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 11539
/proc/meminfo: memFree=562992/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 25 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.306775 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 11539
/proc/meminfo: memFree=562992/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 25 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.706824 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 11539
/proc/meminfo: memFree=562992/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 25 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50285 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 11552
/proc/meminfo: memFree=528160/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 25 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=3448 CPUtime=0
/proc/11550/stat : 11550 (unclasp) S 11538 11538 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 2682605 3530752 272 1283457024 134512640 135121179 4292351984 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11550/statm: 862 272 240 149 0 53 0
[pid=11551] ppid=11538 vsize=2696 CPUtime=0
/proc/11551/stat : 11551 (gringo) S 11538 11538 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 2682605 2760704 281 1283457024 134512640 137056543 4287226512 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11551/statm: 674 281 252 622 0 49 0
[pid=11552] ppid=11538 vsize=40452 CPUtime=1.24
/proc/11552/stat : 11552 (cudf2lp) R 11538 11538 1511 34817 1511 4202496 11508 0 0 0 118 6 0 0 25 0 1 0 2682606 41422848 8604 1283457024 134512640 135786343 4290315776 18446744073709551615 134614624 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11552/statm: 10113 8604 126 311 0 9800 0
Current children cumulated CPU time (s) 1.24
Current children cumulated vsize (KiB) 49188

[startup+3.10414 s]
/proc/loadavg: 1.00 1.03 1.00 3/37 11552
/proc/meminfo: memFree=491284/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=0
/proc/11538/stat : 11538 (aspuncud-trendy) R 11537 11538 1511 34817 1511 4202496 622 2227 0 0 0 0 0 0 18 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=18044 CPUtime=0.04
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 4678 0 0 0 4 0 0 0 18 0 1 0 2682605 18477056 3885 1283457024 134512640 135121179 4292351984 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 4511 3885 275 149 0 3702 0
[pid=11551] ppid=11538 vsize=22372 CPUtime=0.78
/proc/11551/stat : 11551 (gringo) R 11538 11538 1511 34817 1511 4202496 6803 0 0 0 75 3 0 0 18 0 1 0 2682605 22908928 4537 1283457024 134512640 137056543 4287226512 18446744073709551615 134608465 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11551/statm: 5593 4537 268 622 0 4968 0
[pid=11552] ppid=11538 vsize=0 CPUtime=1.97
/proc/11552/stat : 11552 (cudf2lp) Z 11538 11538 1511 34817 1511 4202508 15691 0 0 0 189 8 0 0 25 0 1 0 2682606 0 0 1283457024 0 0 0 0 0 0 0 6 0 18446744071564254338 0 0 17 0 0 0 0
/proc/11552/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.79
Current children cumulated vsize (KiB) 43008

[startup+6.30486 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=503096/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=45332 CPUtime=2.7
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 36524 0 0 0 255 15 0 0 22 0 1 0 2682605 46419968 10135 1283457024 134512640 135121179 4292351984 18446744073709551615 134990531 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11333 10135 328 149 0 10524 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 47924

[startup+12.7075 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=503104/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=44880 CPUtime=9.09
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 114813 0 0 0 858 51 0 0 25 0 1 0 2682605 45957120 10054 1283457024 134512640 135121179 4292351984 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11220 10054 328 149 0 10411 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 47472

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

[startup+12.8074 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=503104/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=44880 CPUtime=9.19
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 115824 0 0 0 867 52 0 0 25 0 1 0 2682605 45957120 10054 1283457024 134512640 135121179 4292351984 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11220 10054 328 149 0 10411 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 47472

[startup+19.2098 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=503104/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=44420 CPUtime=15.6
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 193783 0 0 0 1470 90 0 0 25 0 1 0 2682605 45486080 9945 1283457024 134512640 135121179 4292351984 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11105 9945 328 149 0 10296 0
Current children cumulated CPU time (s) 18.9
Current children cumulated vsize (KiB) 47012

[startup+22.4109 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=502360/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=45768 CPUtime=18.8
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 230032 0 0 0 1770 110 0 0 25 0 1 0 2682605 46866432 10251 1283457024 134512640 135121179 4292351984 18446744073709551615 134990522 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11442 10251 333 149 0 10633 0
Current children cumulated CPU time (s) 22.1
Current children cumulated vsize (KiB) 48360

[startup+23.2113 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=502608/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=44008 CPUtime=19.59
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 240137 0 0 0 1845 114 0 0 25 0 1 0 2682605 45064192 9874 1283457024 134512640 135121179 4292351984 18446744073709551615 134891375 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11002 9874 333 149 0 10193 0
Current children cumulated CPU time (s) 22.89
Current children cumulated vsize (KiB) 46600

[startup+23.6116 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=502608/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=45608 CPUtime=19.99
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 245218 0 0 0 1882 117 0 0 25 0 1 0 2682605 46702592 10237 1283457024 134512640 135121179 4292351984 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11402 10237 333 149 0 10593 0
Current children cumulated CPU time (s) 23.29
Current children cumulated vsize (KiB) 48200

[startup+24.0118 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11552
/proc/meminfo: memFree=502608/1048576 swapFree=0/0
[pid=11538] ppid=11537 vsize=2592 CPUtime=3.3
/proc/11538/stat : 11538 (aspuncud-trendy) S 11537 11538 1511 34817 1511 4202496 622 30968 0 0 0 0 315 15 15 0 1 0 2682604 2654208 297 1283457024 134512640 135304128 4287027856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11538/statm: 648 297 251 194 0 35 0
[pid=11550] ppid=11538 vsize=44856 CPUtime=20.39
/proc/11550/stat : 11550 (unclasp) R 11538 11538 1511 34817 1511 4202496 250096 0 0 0 1920 119 0 0 25 0 1 0 2682605 45932544 10060 1283457024 134512640 135121179 4292351984 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11550/statm: 11214 10060 333 149 0 10405 0
Current children cumulated CPU time (s) 23.69
Current children cumulated vsize (KiB) 47448

Child status: 0
Real time (s): 24.0886
CPU time (s): 23.7815
CPU user time (s): 22.4214
CPU system time (s): 1.36008
CPU usage (%): 98.725
Max. virtual memory (cumulated for all children) (KiB): 87896

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.4214
system time used= 1.36008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 284500
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= 2016
involuntary context switches= 1735

runsolver used 0 second user time and 0.016001 second system time

The end