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/rand149.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand149.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand149.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.06 1.02 0.75 5/39 2236
/proc/meminfo: memFree=765268/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2588 CPUtime=0
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 683334 2650112 279 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/2233/statm: 647 279 234 194 0 34 0
[pid=2234] ppid=2233 vsize=2588 CPUtime=0
/proc/2234/stat : 2234 (aspuncud-trendy) S 2233 2233 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 683334 2650112 133 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/2234/statm: 647 133 87 194 0 34 0
[pid=2235] ppid=2234 vsize=2588 CPUtime=0
/proc/2235/stat : 2235 (aspuncud-trendy) R 2234 2233 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 683335 2650112 150 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2235/statm: 647 150 104 194 0 34 0
[pid=2236] ppid=2235 vsize=2588 CPUtime=0
/proc/2236/stat : 2236 (aspuncud-trendy) R 2235 2233 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 683335 2650112 46 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2236/statm: 647 46 0 194 0 34 0

[startup+0.18297 s]
/proc/loadavg: 1.06 1.02 0.75 5/39 2236
/proc/meminfo: memFree=765268/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=0.01
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 2231 0 0 0 1 0 0 25 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.207343 s]
/proc/loadavg: 1.06 1.02 0.75 5/39 2236
/proc/meminfo: memFree=765268/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=0.01
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 2231 0 0 0 1 0 0 25 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.306944 s]
/proc/loadavg: 1.06 1.02 0.75 5/39 2236
/proc/meminfo: memFree=765268/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=0.01
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 2231 0 0 0 1 0 0 25 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.708497 s]
/proc/loadavg: 1.06 1.02 0.75 5/39 2236
/proc/meminfo: memFree=765268/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=0.01
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 2231 0 0 0 1 0 0 25 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50704 s]
/proc/loadavg: 1.06 1.02 0.75 2/40 2247
/proc/meminfo: memFree=728924/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=0.01
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 2231 0 0 0 1 0 0 25 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=3440 CPUtime=0
/proc/2245/stat : 2245 (unclasp) S 2233 2233 1511 34817 1511 4202496 406 0 0 0 0 0 0 0 25 0 1 0 683336 3522560 271 1283457024 134512640 135121179 4287929264 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/2245/statm: 860 271 240 149 0 51 0
[pid=2246] ppid=2233 vsize=2696 CPUtime=0
/proc/2246/stat : 2246 (gringo) S 2233 2233 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 683336 2760704 281 1283457024 134512640 137056543 4289207408 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/2246/statm: 674 281 252 622 0 49 0
[pid=2247] ppid=2233 vsize=40452 CPUtime=1.34
/proc/2247/stat : 2247 (cudf2lp) R 2233 2233 1511 34817 1511 4202496 11617 0 0 0 132 2 0 0 25 0 1 0 683336 41422848 8713 1283457024 134512640 135786343 4287488848 18446744073709551615 134584227 0 0 6 0 0 0 0 17 0 0 0 0
/proc/2247/statm: 10113 8713 126 311 0 9800 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 49180

[startup+3.10947 s]
/proc/loadavg: 1.13 1.04 0.75 3/40 2247
/proc/meminfo: memFree=690084/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=2.05
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 17922 0 0 0 1 198 6 18 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=21868 CPUtime=0.11
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 5650 0 0 0 11 0 0 0 18 0 1 0 683336 22392832 4857 1283457024 134512640 135121179 4287929264 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 5467 4857 277 149 0 4658 0
[pid=2246] ppid=2233 vsize=27892 CPUtime=0.77
/proc/2246/stat : 2246 (gringo) R 2233 2233 1511 34817 1511 4202496 8118 0 0 0 72 5 0 0 18 0 1 0 683336 28561408 5723 1283457024 134512640 137056543 4289207408 18446744073709551615 134803813 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2246/statm: 6973 5723 268 622 0 6348 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 52352

[startup+6.31072 s]
/proc/loadavg: 1.13 1.04 0.75 2/38 2247
/proc/meminfo: memFree=704872/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45572 CPUtime=2.87
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 34124 0 0 0 272 15 0 0 23 0 1 0 683336 46665728 10212 1283457024 134512640 135121179 4287929264 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11393 10212 328 149 0 10584 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 48164

[startup+12.7134 s]
/proc/loadavg: 1.11 1.04 0.75 2/38 2247
/proc/meminfo: memFree=704872/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=44876 CPUtime=9.27
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 114500 0 0 0 884 43 0 0 25 0 1 0 683336 45953024 10058 1283457024 134512640 135121179 4287929264 18446744073709551615 134713294 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11219 10058 328 149 0 10410 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 47468

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

[startup+12.8134 s]
/proc/loadavg: 1.11 1.04 0.75 2/38 2247
/proc/meminfo: memFree=704872/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=44876 CPUtime=9.37
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 115856 0 0 0 893 44 0 0 25 0 1 0 683336 45953024 10058 1283457024 134512640 135121179 4287929264 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11219 10058 328 149 0 10410 0
Current children cumulated CPU time (s) 12.65
Current children cumulated vsize (KiB) 47468

[startup+19.2054 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704748/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45312 CPUtime=15.75
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 177283 0 0 0 1499 76 0 0 25 0 1 0 683336 46399488 10163 1283457024 134512640 135121179 4287929264 18446744073709551615 134734434 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11328 10163 333 149 0 10519 0
Current children cumulated CPU time (s) 19.03
Current children cumulated vsize (KiB) 47904

[startup+22.4065 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704624/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45316 CPUtime=18.94
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 206295 0 0 0 1807 87 0 0 25 0 1 0 683336 46403584 10163 1283457024 134512640 135121179 4287929264 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11329 10163 333 149 0 10520 0
Current children cumulated CPU time (s) 22.22
Current children cumulated vsize (KiB) 47908

[startup+23.2068 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704376/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45152 CPUtime=19.74
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 215354 0 0 0 1886 88 0 0 25 0 1 0 683336 46235648 10122 1283457024 134512640 135121179 4287929264 18446744073709551615 134891050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11288 10122 333 149 0 10479 0
Current children cumulated CPU time (s) 23.02
Current children cumulated vsize (KiB) 47744

[startup+24.0071 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704376/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45152 CPUtime=20.54
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 224168 0 0 0 1963 91 0 0 25 0 1 0 683336 46235648 10122 1283457024 134512640 135121179 4287929264 18446744073709551615 134611141 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11288 10122 333 149 0 10479 0
Current children cumulated CPU time (s) 23.82
Current children cumulated vsize (KiB) 47744

[startup+24.4072 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704128/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=45152 CPUtime=20.94
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 228533 0 0 0 2003 91 0 0 25 0 1 0 683336 46235648 10124 1283457024 134512640 135121179 4287929264 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 11288 10124 333 149 0 10479 0
Current children cumulated CPU time (s) 24.22
Current children cumulated vsize (KiB) 47744

[startup+24.5073 s]
/proc/loadavg: 1.10 1.04 0.76 2/38 2247
/proc/meminfo: memFree=704128/1048576 swapFree=0/0
[pid=2233] ppid=2232 vsize=2592 CPUtime=3.28
/proc/2233/stat : 2233 (aspuncud-trendy) S 2232 2233 1511 34817 1511 4202496 618 31130 0 0 0 1 314 13 15 0 1 0 683334 2654208 297 1283457024 134512640 135304128 4291227280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2233/statm: 648 297 251 194 0 35 0
[pid=2245] ppid=2233 vsize=43248 CPUtime=21.04
/proc/2245/stat : 2245 (unclasp) R 2233 2233 1511 34817 1511 4202496 229229 0 0 0 2013 91 0 0 25 0 1 0 683336 44285952 9737 1283457024 134512640 135121179 4287929264 18446744073709551615 4157729712 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/2245/statm: 10812 9737 342 149 0 10003 0
Current children cumulated CPU time (s) 24.32
Current children cumulated vsize (KiB) 45840

Child status: 0
Real time (s): 24.5316
CPU time (s): 24.3575
CPU user time (s): 23.2815
CPU system time (s): 1.07607
CPU usage (%): 99.2904
Max. virtual memory (cumulated for all children) (KiB): 88104

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.2815
system time used= 1.07607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263494
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= 2023
involuntary context switches= 1755

runsolver used 0 second user time and 0.012 second system time

The end