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/201012070034/aspcud-trendy-1.3/rand165.sarge-etch.cudf.sarge-etch.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch/rand165.sarge-etch.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand165.sarge-etch.cudf.sarge-etch.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.07 1.02 1.00 2/41 9020
/proc/meminfo: memFree=932532/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=3024 CPUtime=0
/proc/9020/stat : 9020 (runsolver) D 9019 9020 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 878834103 3096576 93 1283457024 134512640 134586868 4291386848 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/9020/statm: 756 93 62 19 0 54 0

[startup+0.158202 s]
/proc/loadavg: 1.07 1.02 1.00 2/41 9020
/proc/meminfo: memFree=932532/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=0
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 2213 0 3 0 0 0 0 25 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.20618 s]
/proc/loadavg: 1.07 1.02 1.00 2/41 9020
/proc/meminfo: memFree=932532/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=0
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 2213 0 3 0 0 0 0 25 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.308908 s]
/proc/loadavg: 1.07 1.02 1.00 2/41 9020
/proc/meminfo: memFree=932532/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=0
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 2213 0 3 0 0 0 0 25 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.708983 s]
/proc/loadavg: 1.07 1.02 1.00 2/41 9020
/proc/meminfo: memFree=932532/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=0
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 2213 0 3 0 0 0 0 25 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50939 s]
/proc/loadavg: 1.07 1.02 1.00 2/44 9034
/proc/meminfo: memFree=908192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=17428 CPUtime=0.15
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 4531 0 19 0 14 1 0 0 18 0 1 0 878834107 17846272 4033 1283457024 134512640 136223643 4292391168 18446744073709551615 135023283 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 4357 4033 187 418 0 3937 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 20020

[startup+3.10973 s]
/proc/loadavg: 1.07 1.02 1.00 2/43 9034
/proc/meminfo: memFree=908644/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=20828 CPUtime=1.75
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 5652 0 19 0 172 3 0 0 20 0 1 0 878834107 21327872 4757 1283457024 134512640 136223643 4292391168 18446744073709551615 134631716 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 5207 4757 225 418 0 4787 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 23420

[startup+6.31048 s]
/proc/loadavg: 1.06 1.02 1.00 2/43 9034
/proc/meminfo: memFree=907908/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=27692 CPUtime=4.95
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 7348 0 19 0 488 7 0 0 25 0 1 0 878834107 28356608 6453 1283457024 134512640 136223643 4292391168 18446744073709551615 134930025 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 6923 6453 225 418 0 6503 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 30284

[startup+12.7116 s]
/proc/loadavg: 1.06 1.01 1.00 2/43 9034
/proc/meminfo: memFree=893896/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=36052 CPUtime=11.36
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 9450 0 19 0 1128 8 0 0 25 0 1 0 878834107 36917248 8555 1283457024 134512640 136223643 4292391168 18446744073709551615 134924290 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 9013 8555 225 418 0 8593 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 38644

[startup+25.5048 s]
/proc/loadavg: 1.04 1.01 1.00 2/43 9034
/proc/meminfo: memFree=885464/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=45196 CPUtime=24.12
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 11719 0 19 0 2404 8 0 0 25 0 1 0 878834107 46280704 10824 1283457024 134512640 136223643 4292391168 18446744073709551615 134631219 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 11299 10824 225 418 0 10879 0
Current children cumulated CPU time (s) 25.25
Current children cumulated vsize (KiB) 47788

[startup+51.1113 s]
/proc/loadavg: 1.03 1.01 1.00 2/42 9034
/proc/meminfo: memFree=867808/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=61964 CPUtime=49.7
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 15908 0 19 0 4962 8 0 0 25 0 1 0 878834107 63451136 15013 1283457024 134512640 136223643 4292391168 18446744073709551615 134664680 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 15491 15013 225 418 0 15071 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 64556

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

[startup+51.2114 s]
/proc/loadavg: 1.03 1.01 1.00 2/42 9034
/proc/meminfo: memFree=867808/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=61964 CPUtime=49.8
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 15908 0 19 0 4972 8 0 0 25 0 1 0 878834107 63451136 15013 1283457024 134512640 136223643 4292391168 18446744073709551615 134704895 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 15491 15013 225 418 0 15071 0
Current children cumulated CPU time (s) 50.93
Current children cumulated vsize (KiB) 64556

[startup+57.6029 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=867684/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=61964 CPUtime=56.18
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 15917 0 19 0 5610 8 0 0 25 0 1 0 878834107 63451136 15022 1283457024 134512640 136223643 4292391168 18446744073709551615 134931073 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 15491 15022 225 418 0 15071 0
Current children cumulated CPU time (s) 57.31
Current children cumulated vsize (KiB) 64556

[startup+60.8036 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851812/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=59.39
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 5929 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 135603047 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 60.52
Current children cumulated vsize (KiB) 81100

[startup+62.404 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=60.99
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 6089 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 62.12
Current children cumulated vsize (KiB) 81100

[startup+64.0044 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=62.59
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 6249 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 134711968 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 63.72
Current children cumulated vsize (KiB) 81100

[startup+64.8046 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=63.39
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 6329 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 134917909 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 64.52
Current children cumulated vsize (KiB) 81100

[startup+65.0047 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=63.59
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 6349 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 64.72
Current children cumulated vsize (KiB) 81100

[startup+65.1047 s]
/proc/loadavg: 1.02 1.01 1.00 2/42 9034
/proc/meminfo: memFree=851192/1048576 swapFree=2080288/2097144
[pid=9020] ppid=9019 vsize=2592 CPUtime=1.13
/proc/9020/stat : 9020 (aspcud-trendy-1) S 9019 9020 4159 34819 4229 4202496 619 14624 0 40 0 0 108 5 15 0 1 0 878834103 2654208 299 1283457024 134512640 135304128 4287232688 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9020/statm: 648 299 253 194 0 34 0
[pid=9032] ppid=9020 vsize=78508 CPUtime=63.69
/proc/9032/stat : 9032 (clasp) R 9020 9020 4159 34819 4229 4202496 20051 0 19 0 6359 10 0 0 25 0 1 0 878834107 80392192 19156 1283457024 134512640 136223643 4292391168 18446744073709551615 134907819 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9032/statm: 19627 19156 225 418 0 19207 0
Current children cumulated CPU time (s) 64.82
Current children cumulated vsize (KiB) 81100

Child status: 0
Real time (s): 65.1744
CPU time (s): 64.8641
CPU user time (s): 64.68
CPU system time (s): 0.184011
CPU usage (%): 99.5238
Max. virtual memory (cumulated for all children) (KiB): 81100

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 64.68
system time used= 0.184011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 38921
page faults= 61
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1235
involuntary context switches= 1912

runsolver used 0 second user time and 0.004 second system time

The end