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/rand348.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand348.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand348.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.02 1.00 4/35 9685
/proc/meminfo: memFree=535256/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2592 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 25 0 1 0 2274279 2654208 280 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/9683/statm: 648 280 234 194 0 35 0
[pid=9684] ppid=9683 vsize=2592 CPUtime=0
/proc/9684/stat : 9684 (aspuncud-trendy) S 9683 9683 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 25 0 1 0 2274280 2654208 134 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/9684/statm: 648 134 87 194 0 35 0
[pid=9685] ppid=9684 vsize=2592 CPUtime=0
/proc/9685/stat : 9685 (aspuncud-trendy) R 9684 9683 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 2274280 2654208 151 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9685/statm: 648 151 104 194 0 35 0
[pid=9686] ppid=9685 vsize=2592 CPUtime=0
/proc/9686/stat : 9686 (aspuncud-trendy) R 9685 9683 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2274280 2654208 47 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9686/statm: 648 47 0 194 0 35 0

[startup+0.206956 s]
/proc/loadavg: 1.00 1.02 1.00 4/35 9685
/proc/meminfo: memFree=535256/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 2227 0 0 0 0 0 0 25 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305449 s]
/proc/loadavg: 1.00 1.02 1.00 4/35 9685
/proc/meminfo: memFree=535256/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 2227 0 0 0 0 0 0 25 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.405467 s]
/proc/loadavg: 1.00 1.02 1.00 4/35 9685
/proc/meminfo: memFree=535256/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 2227 0 0 0 0 0 0 25 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.712325 s]
/proc/loadavg: 1.00 1.02 1.00 4/35 9685
/proc/meminfo: memFree=535256/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 2227 0 0 0 0 0 0 25 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50153 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 9697
/proc/meminfo: memFree=497768/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=0
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 2227 0 0 0 0 0 0 25 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=3448 CPUtime=0
/proc/9695/stat : 9695 (unclasp) S 9683 9683 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 2274281 3530752 272 1283457024 134512640 135121179 4291204816 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9695/statm: 862 272 240 149 0 53 0
[pid=9696] ppid=9683 vsize=2692 CPUtime=0
/proc/9696/stat : 9696 (gringo) S 9683 9683 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 2274281 2756608 280 1283457024 134512640 137056543 4290657760 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9696/statm: 673 280 252 622 0 48 0
[pid=9697] ppid=9683 vsize=40444 CPUtime=1.32
/proc/9697/stat : 9697 (cudf2lp) R 9683 9683 1511 34817 1511 4202496 11542 0 0 0 128 4 0 0 25 0 1 0 2274281 41414656 8637 1283457024 134512640 135786343 4289572176 18446744073709551615 135044613 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9697/statm: 10111 8637 126 311 0 9798 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 49180

[startup+3.11408 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 9697
/proc/meminfo: memFree=458968/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=2.12
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 17918 0 0 0 0 205 7 18 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=19484 CPUtime=0.07
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 5014 0 0 0 7 0 0 0 18 0 1 0 2274281 19951616 4220 1283457024 134512640 135121179 4291204816 18446744073709551615 4158421639 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 4871 4220 277 149 0 4062 0
[pid=9696] ppid=9683 vsize=23872 CPUtime=0.73
/proc/9696/stat : 9696 (gringo) R 9683 9683 1511 34817 1511 4202496 7191 0 0 0 71 2 0 0 18 0 1 0 2274281 24444928 4924 1283457024 134512640 137056543 4290657760 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9696/statm: 5968 4924 268 622 0 5343 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 45952

[startup+6.31499 s]
/proc/loadavg: 1.08 1.04 1.01 2/35 9697
/proc/meminfo: memFree=475376/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=45208 CPUtime=2.79
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 35279 0 0 0 272 7 0 0 22 0 1 0 2274281 46292992 10131 1283457024 134512640 135121179 4291204816 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11302 10131 328 149 0 10493 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 47804

[startup+12.707 s]
/proc/loadavg: 1.08 1.04 1.00 2/35 9697
/proc/meminfo: memFree=475376/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=44456 CPUtime=9.16
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 112478 0 0 0 880 36 0 0 25 0 1 0 2274281 45522944 9943 1283457024 134512640 135121179 4291204816 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11114 9943 328 149 0 10305 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 47052

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

[startup+12.9071 s]
/proc/loadavg: 1.08 1.04 1.00 2/35 9697
/proc/meminfo: memFree=475376/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=44456 CPUtime=9.36
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 114837 0 0 0 898 38 0 0 25 0 1 0 2274281 45522944 9943 1283457024 134512640 135121179 4291204816 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11114 9943 328 149 0 10305 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 47052

[startup+19.3094 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=45368 CPUtime=15.75
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 176892 0 0 0 1512 63 0 0 25 0 1 0 2274281 46456832 10183 1283457024 134512640 135121179 4291204816 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11342 10183 333 149 0 10533 0
Current children cumulated CPU time (s) 19.08
Current children cumulated vsize (KiB) 47964

[startup+22.5105 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=44676 CPUtime=18.95
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 217468 0 0 0 1811 84 0 0 25 0 1 0 2274281 45748224 10016 1283457024 134512640 135121179 4291204816 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11169 10016 333 149 0 10360 0
Current children cumulated CPU time (s) 22.28
Current children cumulated vsize (KiB) 47272

[startup+23.3108 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=45588 CPUtime=19.75
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 227225 0 0 0 1889 86 0 0 25 0 1 0 2274281 46682112 10068 1283457024 134512640 135121179 4291204816 18446744073709551615 134990541 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11397 10068 333 149 0 10588 0
Current children cumulated CPU time (s) 23.08
Current children cumulated vsize (KiB) 48184

[startup+23.7109 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=45588 CPUtime=20.15
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 232133 0 0 0 1926 89 0 0 25 0 1 0 2274281 46682112 10244 1283457024 134512640 135121179 4291204816 18446744073709551615 134980958 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11397 10244 333 149 0 10588 0
Current children cumulated CPU time (s) 23.48
Current children cumulated vsize (KiB) 48184

[startup+23.911 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=45428 CPUtime=20.35
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 234693 0 0 0 1945 90 0 0 25 0 1 0 2274281 46518272 10197 1283457024 134512640 135121179 4291204816 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11357 10197 333 149 0 10548 0
Current children cumulated CPU time (s) 23.68
Current children cumulated vsize (KiB) 48024

[startup+24.011 s]
/proc/loadavg: 1.06 1.03 1.00 2/35 9697
/proc/meminfo: memFree=475004/1048576 swapFree=0/0
[pid=9683] ppid=9682 vsize=2596 CPUtime=3.33
/proc/9683/stat : 9683 (aspuncud-trendy) S 9682 9683 1511 34817 1511 4202496 625 31100 0 0 0 0 321 12 15 0 1 0 2274279 2658304 298 1283457024 134512640 135304128 4290381248 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9683/statm: 649 298 251 194 0 36 0
[pid=9695] ppid=9683 vsize=44676 CPUtime=20.45
/proc/9695/stat : 9695 (unclasp) R 9683 9683 1511 34817 1511 4202496 235864 0 0 0 1955 90 0 0 25 0 1 0 2274281 45748224 10016 1283457024 134512640 135121179 4291204816 18446744073709551615 134643485 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9695/statm: 11169 10016 333 149 0 10360 0
Current children cumulated CPU time (s) 23.78
Current children cumulated vsize (KiB) 47272

Child status: 0
Real time (s): 24.0719
CPU time (s): 23.8575
CPU user time (s): 22.8014
CPU system time (s): 1.05607
CPU usage (%): 99.1092
Max. virtual memory (cumulated for all children) (KiB): 87688

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.8014
system time used= 1.05607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 270097
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= 2015
involuntary context switches= 1760

runsolver used 0 second user time and 0.004 second system time

The end