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/rand208.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand208.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand208.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.00 1.00 4/35 4099
/proc/meminfo: memFree=619784/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2584 CPUtime=0
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 1086865 2646016 279 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/4096/statm: 646 279 234 194 0 33 0
[pid=4097] ppid=4096 vsize=2584 CPUtime=0
/proc/4097/stat : 4097 (aspuncud-trendy) S 4096 4096 1511 34817 1511 4202560 119 0 0 0 0 0 0 0 18 0 1 0 1086865 2646016 133 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/4097/statm: 646 133 87 194 0 33 0
[pid=4098] ppid=4097 vsize=2584 CPUtime=0
/proc/4098/stat : 4098 (aspuncud-trendy) R 4097 4096 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 1086865 2646016 150 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/4098/statm: 646 150 104 194 0 33 0

[startup+0.122657 s]
/proc/loadavg: 1.00 1.00 1.00 4/35 4099
/proc/meminfo: memFree=619784/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=0.01
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 2229 0 0 0 1 0 0 25 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.206674 s]
/proc/loadavg: 1.00 1.00 1.00 4/35 4099
/proc/meminfo: memFree=619784/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=0.01
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 2229 0 0 0 1 0 0 25 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.30666 s]
/proc/loadavg: 1.00 1.00 1.00 4/35 4099
/proc/meminfo: memFree=619784/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=0.01
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 2229 0 0 0 1 0 0 25 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.714058 s]
/proc/loadavg: 1.00 1.00 1.00 4/35 4099
/proc/meminfo: memFree=619784/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=0.01
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 2229 0 0 0 1 0 0 25 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.50673 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 4110
/proc/meminfo: memFree=583596/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=0.01
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 2229 0 0 0 1 0 0 25 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=3444 CPUtime=0
/proc/4108/stat : 4108 (unclasp) S 4096 4096 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1086866 3526656 272 1283457024 134512640 135121179 4291809136 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4108/statm: 861 272 240 149 0 52 0
[pid=4109] ppid=4096 vsize=2696 CPUtime=0
/proc/4109/stat : 4109 (gringo) S 4096 4096 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1086866 2760704 281 1283457024 134512640 137056543 4288752656 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4109/statm: 674 281 252 622 0 49 0
[pid=4110] ppid=4096 vsize=40452 CPUtime=1.35
/proc/4110/stat : 4110 (cudf2lp) R 4096 4096 1511 34817 1511 4202496 11604 0 0 0 128 7 0 0 25 0 1 0 1086866 41422848 8700 1283457024 134512640 135786343 4289234176 18446744073709551615 135044426 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4110/statm: 10113 8700 126 311 0 9800 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 49180

[startup+3.1154 s]
/proc/loadavg: 1.08 1.02 1.01 2/37 4110
/proc/meminfo: memFree=544884/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=2.05
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 17920 0 0 0 1 192 12 18 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=21620 CPUtime=0.06
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 5573 0 0 0 4 2 0 0 18 0 1 0 1086866 22138880 4780 1283457024 134512640 135121179 4291809136 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 5405 4780 277 149 0 4596 0
[pid=4109] ppid=4096 vsize=34096 CPUtime=0.85
/proc/4109/stat : 4109 (gringo) R 4096 4096 1511 34817 1511 4202496 7954 0 0 0 85 0 0 0 18 0 1 0 1086866 34914304 5688 1283457024 134512640 137056543 4288752656 18446744073709551615 136325020 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4109/statm: 8524 5688 268 622 0 7899 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 58304

[startup+6.3065 s]
/proc/loadavg: 1.08 1.02 1.01 2/35 4110
/proc/meminfo: memFree=558928/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45276 CPUtime=2.77
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 27824 0 0 0 268 9 0 0 22 0 1 0 1086866 46362624 10150 1283457024 134512640 135121179 4291809136 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11319 10150 333 149 0 10510 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 47864

[startup+12.7088 s]
/proc/loadavg: 1.07 1.02 1.00 2/35 4110
/proc/meminfo: memFree=558812/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45724 CPUtime=9.16
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 109202 0 0 0 858 58 0 0 25 0 1 0 1086866 46821376 10262 1283457024 134512640 135121179 4291809136 18446744073709551615 134891453 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11431 10262 333 149 0 10622 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 48312

[startup+25.5044 s]
/proc/loadavg: 1.06 1.02 1.00 2/37 4112
/proc/meminfo: memFree=558168/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45724 CPUtime=21.96
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 236157 0 0 0 2087 109 0 0 25 0 1 0 1086866 46821376 10269 1283457024 134512640 135121179 4291809136 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11431 10269 333 149 0 10622 0
Current children cumulated CPU time (s) 25.34
Current children cumulated vsize (KiB) 48312

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

[startup+25.6045 s]
/proc/loadavg: 1.06 1.02 1.00 2/37 4112
/proc/meminfo: memFree=558168/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45724 CPUtime=22.06
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 237543 0 0 0 2096 110 0 0 25 0 1 0 1086866 46821376 10275 1283457024 134512640 135121179 4291809136 18446744073709551615 4159091818 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11431 10275 333 149 0 10622 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 48312

[startup+28.8057 s]
/proc/loadavg: 1.05 1.02 1.00 2/37 4113
/proc/meminfo: memFree=558416/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45724 CPUtime=25.25
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 275986 0 0 0 2393 132 0 0 25 0 1 0 1086866 46821376 10275 1283457024 134512640 135121179 4291809136 18446744073709551615 134734446 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11431 10275 333 149 0 10622 0
Current children cumulated CPU time (s) 28.63
Current children cumulated vsize (KiB) 48312

[startup+29.6059 s]
/proc/loadavg: 1.05 1.02 1.00 2/37 4113
/proc/meminfo: memFree=558416/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45276 CPUtime=26.05
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 285374 0 0 0 2467 138 0 0 25 0 1 0 1086866 46362624 10157 1283457024 134512640 135121179 4291809136 18446744073709551615 4159091781 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11319 10157 333 149 0 10510 0
Current children cumulated CPU time (s) 29.43
Current children cumulated vsize (KiB) 47864

[startup+30.4062 s]
/proc/loadavg: 1.05 1.02 1.00 2/37 4113
/proc/meminfo: memFree=558416/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=46656 CPUtime=26.86
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 294695 0 0 0 2540 146 0 0 25 0 1 0 1086866 47775744 10508 1283457024 134512640 135121179 4291809136 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11664 10508 333 149 0 10855 0
Current children cumulated CPU time (s) 30.24
Current children cumulated vsize (KiB) 49244

[startup+30.8063 s]
/proc/loadavg: 1.05 1.02 1.00 2/37 4113
/proc/meminfo: memFree=558788/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45276 CPUtime=27.26
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 299372 0 0 0 2576 150 0 0 25 0 1 0 1086866 46362624 10164 1283457024 134512640 135121179 4291809136 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11319 10164 333 149 0 10510 0
Current children cumulated CPU time (s) 30.64
Current children cumulated vsize (KiB) 47864

[startup+30.9064 s]
/proc/loadavg: 1.05 1.02 1.00 2/37 4113
/proc/meminfo: memFree=558788/1048576 swapFree=0/0
[pid=4096] ppid=4095 vsize=2588 CPUtime=3.38
/proc/4096/stat : 4096 (aspuncud-trendy) S 4095 4096 1511 34817 1511 4202496 620 31262 0 0 0 1 322 15 15 0 1 0 1086865 2650112 297 1283457024 134512640 135304128 4289719584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4096/statm: 647 297 251 194 0 34 0
[pid=4108] ppid=4096 vsize=45724 CPUtime=27.36
/proc/4108/stat : 4108 (unclasp) R 4096 4096 1511 34817 1511 4202496 300176 0 0 0 2586 150 0 0 25 0 1 0 1086866 46821376 10278 1283457024 134512640 135121179 4291809136 18446744073709551615 134733425 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4108/statm: 11431 10278 342 149 0 10622 0
Current children cumulated CPU time (s) 30.74
Current children cumulated vsize (KiB) 48312

Child status: 0
Real time (s): 30.9581
CPU time (s): 30.8099
CPU user time (s): 29.1218
CPU system time (s): 1.6881
CPU usage (%): 99.5215
Max. virtual memory (cumulated for all children) (KiB): 88224

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 29.1218
system time used= 1.6881
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 334588
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= 2080
involuntary context switches= 1884

runsolver used 0 second user time and 0 second system time

The end