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/rand917.cudf.s-e-l-s-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand917.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand917.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.16 1.15 1.06 3/35 15000
/proc/meminfo: memFree=405764/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2588 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) R 14998 14999 1511 34817 1511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 3348889 2650112 280 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/14999/statm: 647 280 234 194 0 34 0
[pid=15000] ppid=14999 vsize=2588 CPUtime=0
/proc/15000/stat : 15000 (aspuncud-trendy) R 14999 14999 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3348889 2650112 46 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/15000/statm: 647 46 0 194 0 34 0

[startup+0.202742 s]
/proc/loadavg: 1.16 1.15 1.06 3/35 15000
/proc/meminfo: memFree=405764/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.306737 s]
/proc/loadavg: 1.16 1.15 1.06 3/35 15000
/proc/meminfo: memFree=405764/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.406746 s]
/proc/loadavg: 1.16 1.15 1.06 3/35 15000
/proc/meminfo: memFree=405764/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.708936 s]
/proc/loadavg: 1.16 1.15 1.06 3/35 15000
/proc/meminfo: memFree=405764/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50282 s]
/proc/loadavg: 1.16 1.15 1.06 2/38 15013
/proc/meminfo: memFree=366980/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=3440 CPUtime=0
/proc/15011/stat : 15011 (unclasp) S 14999 14999 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 3348890 3522560 271 1283457024 134512640 135121179 4287523664 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15011/statm: 860 271 240 149 0 51 0
[pid=15012] ppid=14999 vsize=2692 CPUtime=0
/proc/15012/stat : 15012 (gringo) S 14999 14999 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 3348890 2756608 281 1283457024 134512640 137056543 4290467248 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15012/statm: 673 281 252 622 0 48 0
[pid=15013] ppid=14999 vsize=40668 CPUtime=1.26
/proc/15013/stat : 15013 (cudf2lp) R 14999 14999 1511 34817 1511 4202496 11616 0 0 0 122 4 0 0 25 0 1 0 3348890 41644032 8711 1283457024 134512640 135786343 4286657168 18446744073709551615 134566250 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15013/statm: 10167 8711 126 311 0 9854 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 49392

[startup+3.11153 s]
/proc/loadavg: 1.16 1.15 1.06 4/38 15013
/proc/meminfo: memFree=328260/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=0
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 2227 0 0 0 0 0 0 25 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=18964 CPUtime=0.02
/proc/15011/stat : 15011 (unclasp) S 14999 14999 1511 34817 1511 4202496 4925 0 0 0 2 0 0 0 18 0 1 0 3348890 19419136 4131 1283457024 134512640 135121179 4287523664 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15011/statm: 4741 4131 275 149 0 3932 0
[pid=15012] ppid=14999 vsize=22388 CPUtime=0.73
/proc/15012/stat : 15012 (gringo) S 14999 14999 1511 34817 1511 4202496 6952 0 0 0 70 3 0 0 18 0 1 0 3348890 22925312 4685 1283457024 134512640 137056543 4290467248 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/15012/statm: 5597 4685 253 622 0 4972 0
[pid=15013] ppid=14999 vsize=46948 CPUtime=2.1
/proc/15013/stat : 15013 (cudf2lp) R 14999 14999 1511 34817 1511 4202496 16196 0 0 0 204 6 0 0 25 0 1 0 3348890 48074752 11464 1283457024 134512640 135786343 4286657168 18446744073709551615 135044416 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15013/statm: 11737 11464 138 311 0 11424 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 90892

[startup+6.31261 s]
/proc/loadavg: 1.23 1.16 1.06 2/36 15013
/proc/meminfo: memFree=343420/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=47040 CPUtime=2.58
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 25344 0 0 0 253 5 0 0 21 0 1 0 3348890 48168960 10580 1283457024 134512640 135121179 4287523664 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 11760 10580 323 149 0 10951 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 49632

[startup+12.7051 s]
/proc/loadavg: 1.21 1.16 1.06 2/36 15013
/proc/meminfo: memFree=342808/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=46868 CPUtime=8.97
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 107447 0 0 0 857 40 0 0 25 0 1 0 3348890 47992832 10522 1283457024 134512640 135121179 4287523664 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 11717 10522 328 149 0 10908 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 49460

[startup+25.5097 s]
/proc/loadavg: 1.16 1.15 1.06 2/35 15013
/proc/meminfo: memFree=341824/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=47344 CPUtime=21.76
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 226166 0 0 0 2092 84 0 0 25 0 1 0 3348890 48480256 10705 1283457024 134512640 135121179 4287523664 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 11836 10705 333 149 0 11027 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 49936

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

[startup+25.7097 s]
/proc/loadavg: 1.16 1.15 1.06 2/35 15013
/proc/meminfo: memFree=341824/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=47100 CPUtime=21.97
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 228778 0 0 0 2111 86 0 0 25 0 1 0 3348890 48230400 10612 1283457024 134512640 135121179 4287523664 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 11775 10612 333 149 0 10966 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 49692

[startup+28.9107 s]
/proc/loadavg: 1.15 1.15 1.06 2/35 15013
/proc/meminfo: memFree=342072/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=48068 CPUtime=25.17
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 266332 0 0 0 2418 99 0 0 25 0 1 0 3348890 49221632 10854 1283457024 134512640 135121179 4287523664 18446744073709551615 134959949 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 12017 10854 333 149 0 11208 0
Current children cumulated CPU time (s) 28.64
Current children cumulated vsize (KiB) 50660

[startup+30.5112 s]
/proc/loadavg: 1.15 1.15 1.06 2/35 15013
/proc/meminfo: memFree=341824/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=47100 CPUtime=26.77
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 285303 0 0 0 2570 107 0 0 25 0 1 0 3348890 48230400 10612 1283457024 134512640 135121179 4287523664 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 11775 10612 333 149 0 10966 0
Current children cumulated CPU time (s) 30.24
Current children cumulated vsize (KiB) 49692

[startup+31.3115 s]
/proc/loadavg: 1.15 1.15 1.06 2/35 15013
/proc/meminfo: memFree=341824/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=3.47
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 624 32044 0 0 0 0 333 14 15 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
[pid=15011] ppid=14999 vsize=48268 CPUtime=27.57
/proc/15011/stat : 15011 (unclasp) R 14999 14999 1511 34817 1511 4202496 294744 0 0 0 2645 112 0 0 25 0 1 0 3348890 49426432 10904 1283457024 134512640 135121179 4287523664 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15011/statm: 12067 10904 333 149 0 11258 0
Current children cumulated CPU time (s) 31.04
Current children cumulated vsize (KiB) 50860

[startup+31.5115 s]
/proc/loadavg: 1.15 1.15 1.06 2/35 15013
/proc/meminfo: memFree=341824/1048576 swapFree=0/0
[pid=14999] ppid=14998 vsize=2592 CPUtime=31.24
/proc/14999/stat : 14999 (aspuncud-trendy) S 14998 14999 1511 34817 1511 4202496 681 328772 0 0 0 0 2998 126 20 0 1 0 3348889 2654208 298 1283457024 134512640 135304128 4290762256 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/14999/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 31.24
Current children cumulated vsize (KiB) 2592

Child status: 0
Real time (s): 31.5197
CPU time (s): 31.266
CPU user time (s): 30.0019
CPU system time (s): 1.26408
CPU usage (%): 99.1949
Max. virtual memory (cumulated for all children) (KiB): 90892

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 30.0019
system time used= 1.26408
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 331372
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= 2169
involuntary context switches= 1934

runsolver used 0 second user time and 0.012 second system time

The end