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/rand343.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand343.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand343.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 5/38 7830
/proc/meminfo: memFree=577660/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2588 CPUtime=0
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 1893343 2650112 280 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/7827/statm: 647 280 234 194 0 34 0
[pid=7828] ppid=7827 vsize=2588 CPUtime=0
/proc/7828/stat : 7828 (aspuncud-trendy) S 7827 7827 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 1893343 2650112 134 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/7828/statm: 647 134 87 194 0 34 0
[pid=7829] ppid=7828 vsize=2588 CPUtime=0.01
/proc/7829/stat : 7829 (aspuncud-trendy) R 7828 7827 1511 34817 1511 4202560 127 0 0 0 0 1 0 0 25 0 1 0 1893343 2650112 151 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7829/statm: 647 151 104 194 0 34 0
[pid=7830] ppid=7829 vsize=2588 CPUtime=0
/proc/7830/stat : 7830 (aspuncud-trendy) R 7829 7827 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1893343 2650112 47 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7830/statm: 647 47 0 194 0 34 0

[startup+0.1147 s]
/proc/loadavg: 1.00 1.00 1.00 5/38 7830
/proc/meminfo: memFree=577660/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=0.01
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 2230 0 0 0 0 0 1 25 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.206707 s]
/proc/loadavg: 1.00 1.00 1.00 5/38 7830
/proc/meminfo: memFree=577660/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=0.01
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 2230 0 0 0 0 0 1 25 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.306712 s]
/proc/loadavg: 1.00 1.00 1.00 5/38 7830
/proc/meminfo: memFree=577660/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=0.01
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 2230 0 0 0 0 0 1 25 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.706796 s]
/proc/loadavg: 1.00 1.00 1.00 5/38 7830
/proc/meminfo: memFree=577660/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=0.01
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 2230 0 0 0 0 0 1 25 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50678 s]
/proc/loadavg: 1.00 1.00 1.00 2/39 7841
/proc/meminfo: memFree=541836/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=0.01
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 2230 0 0 0 0 0 1 25 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=3444 CPUtime=0
/proc/7839/stat : 7839 (unclasp) S 7827 7827 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1893345 3526656 272 1283457024 134512640 135121179 4288353312 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7839/statm: 861 272 240 149 0 52 0
[pid=7840] ppid=7827 vsize=2696 CPUtime=0
/proc/7840/stat : 7840 (gringo) S 7827 7827 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1893345 2760704 281 1283457024 134512640 137056543 4287695616 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7840/statm: 674 281 252 622 0 49 0
[pid=7841] ppid=7827 vsize=40444 CPUtime=1.32
/proc/7841/stat : 7841 (cudf2lp) R 7827 7827 1511 34817 1511 4202496 11591 0 0 0 122 10 0 0 25 0 1 0 1893345 41414656 8687 1283457024 134512640 135786343 4286786208 18446744073709551615 134609368 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7841/statm: 10111 8687 126 311 0 9798 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 49176

[startup+3.10907 s]
/proc/loadavg: 1.00 1.00 1.00 3/39 7841
/proc/meminfo: memFree=504868/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=1.96
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 17920 0 0 0 0 182 14 18 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=18832 CPUtime=0.09
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 4874 0 0 0 6 3 0 0 18 0 1 0 1893345 19283968 4081 1283457024 134512640 135121179 4288353312 18446744073709551615 4158143254 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 4708 4081 276 149 0 3899 0
[pid=7840] ppid=7827 vsize=23188 CPUtime=0.8
/proc/7840/stat : 7840 (gringo) R 7827 7827 1511 34817 1511 4202496 7052 0 0 0 78 2 0 0 18 0 1 0 1893345 23744512 4786 1283457024 134512640 137056543 4287695616 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7840/statm: 5797 4786 268 622 0 5172 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 44612

[startup+6.31019 s]
/proc/loadavg: 1.08 1.02 1.01 2/37 7841
/proc/meminfo: memFree=517680/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=45052 CPUtime=2.83
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 32153 0 0 0 264 19 0 0 22 0 1 0 1893345 46133248 10102 1283457024 134512640 135121179 4288353312 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11263 10102 333 149 0 10454 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 47644

[startup+12.7128 s]
/proc/loadavg: 1.07 1.02 1.00 2/37 7842
/proc/meminfo: memFree=517556/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=45052 CPUtime=9.23
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 113801 0 0 0 874 49 0 0 25 0 1 0 1893345 46133248 10102 1283457024 134512640 135121179 4288353312 18446744073709551615 134638686 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11263 10102 333 149 0 10454 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 47644

[startup+25.5069 s]
/proc/loadavg: 1.13 1.03 1.01 2/37 7843
/proc/meminfo: memFree=516812/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=44592 CPUtime=22.01
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 240094 0 0 0 2088 113 0 0 25 0 1 0 1893345 45662208 9989 1283457024 134512640 135121179 4288353312 18446744073709551615 134713322 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11148 9989 333 149 0 10339 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 47184

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

[startup+25.6069 s]
/proc/loadavg: 1.13 1.03 1.01 2/37 7843
/proc/meminfo: memFree=516812/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=45056 CPUtime=22.11
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 241566 0 0 0 2096 115 0 0 25 0 1 0 1893345 46137344 10105 1283457024 134512640 135121179 4288353312 18446744073709551615 4159677514 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11264 10105 333 149 0 10455 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 47648

[startup+27.2073 s]
/proc/loadavg: 1.13 1.03 1.01 2/37 7843
/proc/meminfo: memFree=517556/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=46596 CPUtime=23.71
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 260399 0 0 0 2246 125 0 0 25 0 1 0 1893345 47714304 10444 1283457024 134512640 135121179 4288353312 18446744073709551615 134991709 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11649 10444 333 149 0 10840 0
Current children cumulated CPU time (s) 26.96
Current children cumulated vsize (KiB) 49188

[startup+28.0074 s]
/proc/loadavg: 1.13 1.03 1.01 2/37 7844
/proc/meminfo: memFree=517556/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=44592 CPUtime=24.5
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 269818 0 0 0 2322 128 0 0 25 0 1 0 1893345 45662208 9995 1283457024 134512640 135121179 4288353312 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11148 9995 333 149 0 10339 0
Current children cumulated CPU time (s) 27.75
Current children cumulated vsize (KiB) 47184

[startup+28.8076 s]
/proc/loadavg: 1.12 1.03 1.01 2/37 7844
/proc/meminfo: memFree=516812/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=3.25
/proc/7827/stat : 7827 (aspuncud-trendy) S 7826 7827 1511 34817 1511 4202496 617 31123 0 0 0 0 305 20 15 0 1 0 1893343 2654208 298 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7827/statm: 648 298 251 194 0 35 0
[pid=7839] ppid=7827 vsize=45972 CPUtime=25.31
/proc/7839/stat : 7839 (unclasp) R 7827 7827 1511 34817 1511 4202496 279218 0 0 0 2395 136 0 0 25 0 1 0 1893345 47075328 10242 1283457024 134512640 135121179 4288353312 18446744073709551615 134990503 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7839/statm: 11493 10242 333 149 0 10684 0
Current children cumulated CPU time (s) 28.56
Current children cumulated vsize (KiB) 48564

[startup+29.2077 s]
/proc/loadavg: 1.12 1.03 1.01 2/37 7844
/proc/meminfo: memFree=516812/1048576 swapFree=0/0
[pid=7827] ppid=7826 vsize=2592 CPUtime=28.95
/proc/7827/stat : 7827 (aspuncud-trendy) R 7826 7827 1511 34817 1511 4202496 812 316069 0 0 0 0 2736 159 20 0 1 0 1893343 2654208 299 1283457024 134512640 135304128 4292878368 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/7827/statm: 648 299 252 194 0 35 0
Current children cumulated CPU time (s) 28.95
Current children cumulated vsize (KiB) 2592

Child status: 0
Real time (s): 29.2086
CPU time (s): 28.9818
CPU user time (s): 27.3657
CPU system time (s): 1.6161
CPU usage (%): 99.2234
Max. virtual memory (cumulated for all children) (KiB): 87704

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.3657
system time used= 1.6161
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 317090
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= 2033
involuntary context switches= 1823

runsolver used 0 second user time and 0 second system time

The end