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/rand21.cudf.dudf-random.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand21.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.08 1.03 0.97 4/35 3407
/proc/meminfo: memFree=684740/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2592 CPUtime=0
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 958953 2654208 280 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/3405/statm: 648 280 234 194 0 35 0
[pid=3406] ppid=3405 vsize=2592 CPUtime=0
/proc/3406/stat : 3406 (aspuncud-trendy) S 3405 3405 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 958953 2654208 134 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/3406/statm: 648 134 87 194 0 35 0
[pid=3407] ppid=3406 vsize=2592 CPUtime=0.01
/proc/3407/stat : 3407 (aspuncud-trendy) R 3406 3405 1511 34817 1511 4202560 8 0 0 0 0 1 0 0 25 0 1 0 958953 2654208 51 1283457024 134512640 135304128 4291925824 18446744073709551615 4158998147 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3407/statm: 648 51 4 194 0 35 0

[startup+0.206325 s]
/proc/loadavg: 1.08 1.03 0.97 4/35 3407
/proc/meminfo: memFree=684740/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=0.02
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 2229 0 0 0 0 0 2 25 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.306332 s]
/proc/loadavg: 1.08 1.03 0.97 4/35 3407
/proc/meminfo: memFree=684740/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=0.02
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 2229 0 0 0 0 0 2 25 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.406338 s]
/proc/loadavg: 1.08 1.03 0.97 4/35 3407
/proc/meminfo: memFree=684740/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=0.02
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 2229 0 0 0 0 0 2 25 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.713315 s]
/proc/loadavg: 1.08 1.03 0.97 4/35 3407
/proc/meminfo: memFree=684740/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=0.02
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 2229 0 0 0 0 0 2 25 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+1.50642 s]
/proc/loadavg: 1.08 1.03 0.97 2/37 3419
/proc/meminfo: memFree=646516/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=0.02
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 2229 0 0 0 0 0 2 25 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=3444 CPUtime=0
/proc/3417/stat : 3417 (unclasp) S 3405 3405 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 958954 3526656 271 1283457024 134512640 135121179 4287269648 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3417/statm: 861 271 240 149 0 52 0
[pid=3418] ppid=3405 vsize=2696 CPUtime=0
/proc/3418/stat : 3418 (gringo) S 3405 3405 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 958954 2760704 281 1283457024 134512640 137056543 4287650560 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3418/statm: 674 281 252 622 0 49 0
[pid=3419] ppid=3405 vsize=25004 CPUtime=1.3
/proc/3419/stat : 3419 (cudf2lp) R 3405 3405 1511 34817 1511 4202496 7151 0 0 0 130 0 0 0 25 0 1 0 958954 25604096 5558 1283457024 134512640 135786343 4289947056 18446744073709551615 134566162 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3419/statm: 6251 5558 126 311 0 5938 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 33740

[startup+3.10903 s]
/proc/loadavg: 1.08 1.03 0.97 4/37 3419
/proc/meminfo: memFree=616196/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=2.27
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 15130 0 0 0 0 222 5 18 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=15032 CPUtime=0.04
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 3686 0 0 0 3 1 0 0 18 0 1 0 958954 15392768 3164 1283457024 134512640 135121179 4287269648 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 3758 3164 277 149 0 2949 0
[pid=3418] ppid=3405 vsize=18868 CPUtime=0.53
/proc/3418/stat : 3418 (gringo) R 3405 3405 1511 34817 1511 4202496 5150 0 0 0 51 2 0 0 18 0 1 0 958954 19320832 3623 1283457024 134512640 137056543 4287650560 18446744073709551615 136323510 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3418/statm: 4717 3623 268 622 0 4092 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 36496

[startup+6.30999 s]
/proc/loadavg: 1.08 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628628/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=33412 CPUtime=2.87
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 28189 0 0 0 278 9 0 0 24 0 1 0 958954 34213888 7434 1283457024 134512640 135121179 4287269648 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8353 7434 333 149 0 7544 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 36008

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

[startup+6.51009 s]
/proc/loadavg: 1.08 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628628/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=33120 CPUtime=3.07
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 29890 0 0 0 298 9 0 0 24 0 1 0 958954 33914880 7361 1283457024 134512640 135121179 4287269648 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8280 7361 333 149 0 7471 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 35716

[startup+8.11059 s]
/proc/loadavg: 1.07 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628760/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=32476 CPUtime=4.67
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 40522 0 0 0 447 20 0 0 25 0 1 0 958954 33255424 7200 1283457024 134512640 135121179 4287269648 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8119 7200 333 149 0 7310 0
Current children cumulated CPU time (s) 7.84
Current children cumulated vsize (KiB) 35072

[startup+8.91081 s]
/proc/loadavg: 1.07 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628636/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=32620 CPUtime=5.47
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 47483 0 0 0 522 25 0 0 25 0 1 0 958954 33402880 7235 1283457024 134512640 135121179 4287269648 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8155 7235 333 149 0 7346 0
Current children cumulated CPU time (s) 8.64
Current children cumulated vsize (KiB) 35216

[startup+9.711 s]
/proc/loadavg: 1.07 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628636/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=33412 CPUtime=6.27
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 54384 0 0 0 602 25 0 0 25 0 1 0 958954 34213888 7408 1283457024 134512640 135121179 4287269648 18446744073709551615 134990465 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8353 7408 333 149 0 7544 0
Current children cumulated CPU time (s) 9.44
Current children cumulated vsize (KiB) 36008

[startup+10.1111 s]
/proc/loadavg: 1.07 1.03 0.97 2/35 3419
/proc/meminfo: memFree=628140/1048576 swapFree=0/0
[pid=3405] ppid=3404 vsize=2596 CPUtime=3.17
/proc/3405/stat : 3405 (aspuncud-trendy) S 3404 3405 1511 34817 1511 4202496 624 23822 0 0 0 0 309 8 15 0 1 0 958953 2658304 298 1283457024 134512640 135304128 4291925824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3405/statm: 649 298 251 194 0 36 0
[pid=3417] ppid=3405 vsize=32836 CPUtime=6.67
/proc/3417/stat : 3417 (unclasp) R 3405 3405 1511 34817 1511 4202496 56571 0 0 0 642 25 0 0 25 0 1 0 958954 33624064 7341 1283457024 134512640 135121179 4287269648 18446744073709551615 4158084617 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3417/statm: 8209 7341 342 149 0 7400 0
Current children cumulated CPU time (s) 9.84
Current children cumulated vsize (KiB) 35432

Child status: 0
Real time (s): 10.1354
CPU time (s): 9.87262
CPU user time (s): 9.52059
CPU system time (s): 0.352022
CPU usage (%): 97.4071
Max. virtual memory (cumulated for all children) (KiB): 73432

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.5206
system time used= 0.352022
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83657
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= 1532
involuntary context switches= 1313

runsolver used 0 second user time and 0 second system time

The end