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/rand282.cudf.dudf-random.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-random//rand282.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand282.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.19 1.06 1.01 5/36 7138
/proc/meminfo: memFree=653612/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) R 7124 7125 1511 34817 1511 4202496 599 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 297 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/7125/statm: 649 297 250 194 0 36 0
[pid=7136] ppid=7125 vsize=2596 CPUtime=0
/proc/7136/stat : 7136 (aspuncud-trendy) R 7125 7125 1511 34817 1511 4202560 105 0 0 0 0 0 0 0 25 0 1 0 1749917 2658304 127 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/7136/statm: 649 127 79 194 0 36 0
[pid=7137] ppid=7125 vsize=2596 CPUtime=0
/proc/7137/stat : 7137 (aspuncud-trendy) S 7125 7125 1511 34817 1511 4202560 103 0 0 0 0 0 0 0 25 0 1 0 1749917 2658304 127 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 649 127 79 194 0 36 0
[pid=7138] ppid=7125 vsize=2596 CPUtime=0
/proc/7138/stat : 7138 (aspuncud-trendy) R 7125 7125 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1749917 2658304 47 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/7138/statm: 649 47 0 194 0 36 0

[startup+0.14639 s]
/proc/loadavg: 1.19 1.06 1.01 5/36 7138
/proc/meminfo: memFree=653612/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=3440 CPUtime=0
/proc/7136/stat : 7136 (unclasp) S 7125 7125 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1749917 3522560 271 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7136/statm: 860 271 240 149 0 51 0
[pid=7137] ppid=7125 vsize=2692 CPUtime=0
/proc/7137/stat : 7137 (gringo) S 7125 7125 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1749917 2756608 281 1283457024 134512640 137056543 4289676528 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 673 281 252 622 0 48 0
[pid=7138] ppid=7125 vsize=3940 CPUtime=0.1
/proc/7138/stat : 7138 (cudf2lp) R 7125 7125 1511 34817 1511 4202496 914 0 0 0 10 0 0 0 25 0 1 0 1749917 4034560 742 1283457024 134512640 135786343 4288830624 18446744073709551615 134614193 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7138/statm: 985 742 126 311 0 672 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 12668

[startup+0.206392 s]
/proc/loadavg: 1.19 1.06 1.01 5/36 7138
/proc/meminfo: memFree=653612/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=3440 CPUtime=0
/proc/7136/stat : 7136 (unclasp) S 7125 7125 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1749917 3522560 271 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7136/statm: 860 271 240 149 0 51 0
[pid=7137] ppid=7125 vsize=2692 CPUtime=0
/proc/7137/stat : 7137 (gringo) S 7125 7125 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1749917 2756608 281 1283457024 134512640 137056543 4289676528 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 673 281 252 622 0 48 0
[pid=7138] ppid=7125 vsize=5352 CPUtime=0.14
/proc/7138/stat : 7138 (cudf2lp) R 7125 7125 1511 34817 1511 4202496 1316 0 0 0 14 0 0 0 25 0 1 0 1749917 5480448 1055 1283457024 134512640 135786343 4288830624 18446744073709551615 134614422 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7138/statm: 1338 1055 126 311 0 1025 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 14080

[startup+0.306419 s]
/proc/loadavg: 1.19 1.06 1.01 5/36 7138
/proc/meminfo: memFree=653612/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=3440 CPUtime=0
/proc/7136/stat : 7136 (unclasp) S 7125 7125 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1749917 3522560 271 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7136/statm: 860 271 240 149 0 51 0
[pid=7137] ppid=7125 vsize=2692 CPUtime=0
/proc/7137/stat : 7137 (gringo) S 7125 7125 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1749917 2756608 281 1283457024 134512640 137056543 4289676528 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 673 281 252 622 0 48 0
[pid=7138] ppid=7125 vsize=8368 CPUtime=0.23
/proc/7138/stat : 7138 (cudf2lp) R 7125 7125 1511 34817 1511 4202496 2147 0 0 0 23 0 0 0 25 0 1 0 1749917 8568832 1709 1283457024 134512640 135786343 4288830624 18446744073709551615 135052132 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7138/statm: 2092 1709 126 311 0 1779 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 17096

[startup+0.706416 s]
/proc/loadavg: 1.19 1.06 1.01 5/36 7138
/proc/meminfo: memFree=653612/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=3440 CPUtime=0
/proc/7136/stat : 7136 (unclasp) S 7125 7125 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1749917 3522560 271 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7136/statm: 860 271 240 149 0 51 0
[pid=7137] ppid=7125 vsize=2692 CPUtime=0
/proc/7137/stat : 7137 (gringo) S 7125 7125 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1749917 2756608 281 1283457024 134512640 137056543 4289676528 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 673 281 252 622 0 48 0
[pid=7138] ppid=7125 vsize=14520 CPUtime=0.54
/proc/7138/stat : 7138 (cudf2lp) R 7125 7125 1511 34817 1511 4202496 3946 0 0 0 54 0 0 0 25 0 1 0 1749917 14868480 3155 1283457024 134512640 135786343 4288830624 18446744073709551615 134566245 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7138/statm: 3630 3155 126 311 0 3317 0
Current children cumulated CPU time (s) 0.55
Current children cumulated vsize (KiB) 23248

[startup+1.50648 s]
/proc/loadavg: 1.19 1.06 1.01 2/37 7139
/proc/meminfo: memFree=616324/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=0.01
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 2224 0 0 0 0 0 1 25 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=3440 CPUtime=0
/proc/7136/stat : 7136 (unclasp) S 7125 7125 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 1749917 3522560 271 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7136/statm: 860 271 240 149 0 51 0
[pid=7137] ppid=7125 vsize=2692 CPUtime=0
/proc/7137/stat : 7137 (gringo) S 7125 7125 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 1749917 2756608 281 1283457024 134512640 137056543 4289676528 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7137/statm: 673 281 252 622 0 48 0
[pid=7138] ppid=7125 vsize=25000 CPUtime=1.21
/proc/7138/stat : 7138 (cudf2lp) R 7125 7125 1511 34817 1511 4202496 7164 0 0 0 119 2 0 0 25 0 1 0 1749917 25600000 5571 1283457024 134512640 135786343 4288830624 18446744073709551615 134566198 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7138/statm: 6250 5571 126 311 0 5937 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 33728

[startup+3.10748 s]
/proc/loadavg: 1.17 1.06 1.01 2/37 7139
/proc/meminfo: memFree=581140/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=2.19
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 15124 0 0 0 0 211 8 18 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=15032 CPUtime=0.08
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 3691 0 0 0 6 2 0 0 18 0 1 0 1749917 15392768 3169 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 3758 3169 277 149 0 2949 0
[pid=7137] ppid=7125 vsize=18880 CPUtime=0.51
/proc/7137/stat : 7137 (gringo) R 7125 7125 1511 34817 1511 4202496 5166 0 0 0 51 0 0 0 18 0 1 0 1749917 19333120 3639 1283457024 134512640 137056543 4289676528 18446744073709551615 134647254 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7137/statm: 4720 3639 268 622 0 4095 0
Current children cumulated CPU time (s) 2.78
Current children cumulated vsize (KiB) 36508

[startup+6.3085 s]
/proc/loadavg: 1.17 1.06 1.01 2/35 7139
/proc/meminfo: memFree=597788/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=33528 CPUtime=2.93
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 28873 0 0 0 282 11 0 0 23 0 1 0 1749917 34332672 7477 1283457024 134512640 135121179 4287699840 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 8382 7477 331 149 0 7573 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 36124

[startup+12.7108 s]
/proc/loadavg: 1.15 1.06 1.01 2/35 7139
/proc/meminfo: memFree=597052/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=33916 CPUtime=9.32
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 45131 0 0 0 908 24 0 0 25 0 1 0 1749917 34729984 7578 1283457024 134512640 135121179 4287699840 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 8479 7578 332 149 0 7670 0
Current children cumulated CPU time (s) 12.37
Current children cumulated vsize (KiB) 36512

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

[startup+12.8109 s]
/proc/loadavg: 1.15 1.06 1.01 2/35 7139
/proc/meminfo: memFree=597052/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=33916 CPUtime=9.42
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 45131 0 0 0 918 24 0 0 25 0 1 0 1749917 34729984 7578 1283457024 134512640 135121179 4287699840 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 8479 7578 332 149 0 7670 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 36512

[startup+13.6111 s]
/proc/loadavg: 1.15 1.06 1.01 2/35 7139
/proc/meminfo: memFree=596804/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=33528 CPUtime=10.22
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 47154 0 0 0 998 24 0 0 25 0 1 0 1749917 34332672 7481 1283457024 134512640 135121179 4287699840 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 8382 7481 332 149 0 7573 0
Current children cumulated CPU time (s) 13.27
Current children cumulated vsize (KiB) 36124

[startup+14.0113 s]
/proc/loadavg: 1.15 1.06 1.01 2/35 7139
/proc/meminfo: memFree=596804/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=33528 CPUtime=10.62
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 50465 0 0 0 1036 26 0 0 25 0 1 0 1749917 34332672 7481 1283457024 134512640 135121179 4287699840 18446744073709551615 134991709 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 8382 7481 332 149 0 7573 0
Current children cumulated CPU time (s) 13.67
Current children cumulated vsize (KiB) 36124

[startup+14.2118 s]
/proc/loadavg: 1.15 1.06 1.01 2/35 7139
/proc/meminfo: memFree=596804/1048576 swapFree=0/0
[pid=7125] ppid=7124 vsize=2596 CPUtime=3.05
/proc/7125/stat : 7125 (aspuncud-trendy) S 7124 7125 1511 34817 1511 4202496 625 23853 0 0 0 0 296 9 15 0 1 0 1749916 2658304 298 1283457024 134512640 135304128 4289426656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7125/statm: 649 298 251 194 0 36 0
[pid=7136] ppid=7125 vsize=29180 CPUtime=10.81
/proc/7136/stat : 7136 (unclasp) R 7125 7125 1511 34817 1511 4202496 51067 0 0 0 1053 28 0 0 25 0 1 0 1749917 29880320 6776 1283457024 134512640 135121179 4287699840 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/7136/statm: 7295 6776 342 149 0 6486 0
Current children cumulated CPU time (s) 13.86
Current children cumulated vsize (KiB) 31776

Child status: 0
Real time (s): 14.2332
CPU time (s): 13.9049
CPU user time (s): 13.5048
CPU system time (s): 0.400025
CPU usage (%): 97.693
Max. virtual memory (cumulated for all children) (KiB): 73436

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.5048
system time used= 0.400025
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 78183
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= 1544
involuntary context switches= 1355

runsolver used 0 second user time and 0.004 second system time

The end