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/rand390.cudf.dudf-random.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-random//rand390.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand390.cudf.dudf-random.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.18 1.11 1.03 5/37 8979
/proc/meminfo: memFree=494944/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2584 CPUtime=0
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 2132427 2646016 279 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/8977/statm: 646 279 234 194 0 33 0
[pid=8978] ppid=8977 vsize=2584 CPUtime=0
/proc/8978/stat : 8978 (aspuncud-trendy) R 8977 8977 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2132428 2646016 132 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/8978/statm: 646 132 86 194 0 33 0
[pid=8979] ppid=8978 vsize=2584 CPUtime=0
/proc/8979/stat : 8979 (aspuncud-trendy) R 8978 8977 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2132428 2646016 46 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/8979/statm: 646 46 0 194 0 33 0

[startup+0.206148 s]
/proc/loadavg: 1.18 1.11 1.03 5/37 8979
/proc/meminfo: memFree=494944/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.306135 s]
/proc/loadavg: 1.18 1.11 1.03 5/37 8979
/proc/meminfo: memFree=494944/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.406142 s]
/proc/loadavg: 1.18 1.11 1.03 5/37 8979
/proc/meminfo: memFree=494944/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.706168 s]
/proc/loadavg: 1.18 1.11 1.03 5/37 8979
/proc/meminfo: memFree=494944/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.50621 s]
/proc/loadavg: 1.18 1.11 1.03 2/39 8991
/proc/meminfo: memFree=457008/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=3440 CPUtime=0
/proc/8989/stat : 8989 (unclasp) S 8977 8977 1511 34817 1511 4202496 406 0 0 0 0 0 0 0 25 0 1 0 2132429 3522560 271 1283457024 134512640 135121179 4291563312 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8989/statm: 860 271 240 149 0 51 0
[pid=8990] ppid=8977 vsize=2692 CPUtime=0
/proc/8990/stat : 8990 (gringo) S 8977 8977 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 2132429 2756608 281 1283457024 134512640 137056543 4287324848 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8990/statm: 673 281 252 622 0 48 0
[pid=8991] ppid=8977 vsize=25004 CPUtime=1.18
/proc/8991/stat : 8991 (cudf2lp) R 8977 8977 1511 34817 1511 4202496 7095 0 0 0 116 2 0 0 25 0 1 0 2132429 25604096 5503 1283457024 134512640 135786343 4286958288 18446744073709551615 134625617 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8991/statm: 6251 5503 126 311 0 5938 0
Current children cumulated CPU time (s) 1.19
Current children cumulated vsize (KiB) 33724

[startup+3.11209 s]
/proc/loadavg: 1.17 1.11 1.03 2/39 8992
/proc/meminfo: memFree=425780/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=0.01
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 2229 0 0 0 0 0 1 25 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=13264 CPUtime=0.03
/proc/8989/stat : 8989 (unclasp) S 8977 8977 1511 34817 1511 4202496 3222 0 0 0 3 0 0 0 18 0 1 0 2132429 13582336 2701 1283457024 134512640 135121179 4291563312 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8989/statm: 3316 2701 275 149 0 2507 0
[pid=8990] ppid=8977 vsize=16624 CPUtime=0.58
/proc/8990/stat : 8990 (gringo) S 8977 8977 1511 34817 1511 4202496 4655 0 0 0 54 4 0 0 18 0 1 0 2132429 17022976 3129 1283457024 134512640 137056543 4287324848 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/8990/statm: 4156 3129 253 622 0 3531 0
[pid=8991] ppid=8977 vsize=21772 CPUtime=2.05
/proc/8991/stat : 8991 (cudf2lp) R 8977 8977 1511 34817 1511 4202496 12896 0 0 0 199 6 0 0 25 0 1 0 2132429 22294528 5265 1283457024 134512640 135786343 4286958288 18446744073709551615 135191469 0 0 6 0 0 0 0 17 0 0 0 0
/proc/8991/statm: 5443 5265 138 311 0 5130 0
Current children cumulated CPU time (s) 2.67
Current children cumulated vsize (KiB) 54248

[startup+6.30312 s]
/proc/loadavg: 1.17 1.11 1.03 2/37 8992
/proc/meminfo: memFree=438956/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=3.07
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 23847 0 0 0 0 293 14 15 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=32772 CPUtime=2.81
/proc/8989/stat : 8989 (unclasp) R 8977 8977 1511 34817 1511 4202496 28040 0 0 0 271 10 0 0 22 0 1 0 2132429 33558528 7292 1283457024 134512640 135121179 4291563312 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8989/statm: 8193 7292 331 149 0 7384 0
Current children cumulated CPU time (s) 5.88
Current children cumulated vsize (KiB) 35360

[startup+12.7054 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 8993
/proc/meminfo: memFree=438220/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=3.07
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 23847 0 0 0 0 293 14 15 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=33504 CPUtime=9.2
/proc/8989/stat : 8989 (unclasp) R 8977 8977 1511 34817 1511 4202496 45665 0 0 0 902 18 0 0 25 0 1 0 2132429 34308096 7475 1283457024 134512640 135121179 4291563312 18446744073709551615 134734375 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8989/statm: 8376 7475 331 149 0 7567 0
Current children cumulated CPU time (s) 12.27
Current children cumulated vsize (KiB) 36092

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

[startup+12.9055 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 8993
/proc/meminfo: memFree=438220/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=3.07
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 23847 0 0 0 0 293 14 15 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=33504 CPUtime=9.4
/proc/8989/stat : 8989 (unclasp) R 8977 8977 1511 34817 1511 4202496 45665 0 0 0 922 18 0 0 25 0 1 0 2132429 34308096 7475 1283457024 134512640 135121179 4291563312 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8989/statm: 8376 7475 331 149 0 7567 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 36092

[startup+13.706 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 8993
/proc/meminfo: memFree=438220/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=3.07
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 23847 0 0 0 0 293 14 15 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=32776 CPUtime=10.2
/proc/8989/stat : 8989 (unclasp) R 8977 8977 1511 34817 1511 4202496 45826 0 0 0 1001 19 0 0 25 0 1 0 2132429 33562624 7325 1283457024 134512640 135121179 4291563312 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8989/statm: 8194 7325 331 149 0 7385 0
Current children cumulated CPU time (s) 13.27
Current children cumulated vsize (KiB) 35364

[startup+14.1061 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 8993
/proc/meminfo: memFree=438220/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=3.07
/proc/8977/stat : 8977 (aspuncud-trendy) S 8976 8977 1511 34817 1511 4202496 623 23847 0 0 0 0 293 14 15 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
[pid=8989] ppid=8977 vsize=32920 CPUtime=10.61
/proc/8989/stat : 8989 (unclasp) R 8977 8977 1511 34817 1511 4202496 49211 0 0 0 1039 22 0 0 25 0 1 0 2132429 33710080 7329 1283457024 134512640 135121179 4291563312 18446744073709551615 134638758 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/8989/statm: 8230 7329 331 149 0 7421 0
Current children cumulated CPU time (s) 13.68
Current children cumulated vsize (KiB) 35508

[startup+14.5063 s]
/proc/loadavg: 1.14 1.10 1.03 2/37 8993
/proc/meminfo: memFree=438344/1048576 swapFree=0/0
[pid=8977] ppid=8976 vsize=2588 CPUtime=14.07
/proc/8977/stat : 8977 (aspuncud-trendy) R 8976 8977 1511 34817 1511 4202496 802 77338 0 0 0 0 1369 38 20 0 1 0 2132427 2650112 297 1283457024 134512640 135304128 4286732864 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/8977/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 14.07
Current children cumulated vsize (KiB) 2588

Child status: 0
Real time (s): 14.5082
CPU time (s): 14.0929
CPU user time (s): 13.6969
CPU system time (s): 0.396024
CPU usage (%): 97.1375
Max. virtual memory (cumulated for all children) (KiB): 72848

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.6969
system time used= 0.396024
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 78562
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= 1541
involuntary context switches= 1362

runsolver used 0 second user time and 0 second system time

The end