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/201103031013/p2cudf-paranoid-1.12/e8a3eb4c-4c81-11df-8b8c-00163e7a6f5e.cudf.debian.log.runsolver ./p2cudf-paranoid-1.12 /home/misc2010/data/misc4/debian//e8a3eb4c-4c81-11df-8b8c-00163e7a6f5e.cudf /home/misc2010/tmp/201103031013/p2cudf-paranoid-1.12/e8a3eb4c-4c81-11df-8b8c-00163e7a6f5e.cudf.debian.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.06 1.07 2/35 9386
/proc/meminfo: memFree=645308/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=1224 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) R 9385 9386 29493 34817 29493 4194304 120 0 0 0 0 0 0 0 25 0 1 0 75728841 1253376 45 1283457024 134512640 135304128 4289451184 18446744073709551615 4159781716 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9386/statm: 306 45 32 194 0 12 0

[startup+0.146194 s]
/proc/loadavg: 1.07 1.06 1.07 2/35 9386
/proc/meminfo: memFree=645308/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.206245 s]
/proc/loadavg: 1.07 1.06 1.07 2/35 9386
/proc/meminfo: memFree=645308/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.306207 s]
/proc/loadavg: 1.07 1.06 1.07 2/35 9386
/proc/meminfo: memFree=645308/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.706312 s]
/proc/loadavg: 1.07 1.06 1.07 2/35 9386
/proc/meminfo: memFree=645308/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+1.50652 s]
/proc/loadavg: 1.07 1.06 1.07 4/47 9409
/proc/meminfo: memFree=599836/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=881612 CPUtime=1.42
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 21651 0 1 0 134 8 0 0 25 0 10 0 75728846 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220403 18514 1730 10 0 217494 0
[pid=9400/tid=9401] ppid=9388 vsize=881612 CPUtime=0.69
/proc/9400/task/9401/stat : 9401 (java) R 9388 9386 29493 34817 29493 4202560 10806 0 1 0 65 4 0 0 25 0 10 0 75728847 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4095164320 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=881612 CPUtime=0.01
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 1 0 0 18 0 10 0 75728849 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 8 0 0 0 0 0 0 0 25 0 10 0 75728850 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 4 0 0 0 0 0 0 0 25 0 10 0 75728850 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 10 0 75728853 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=881612 CPUtime=0.24
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 24 0 0 0 23 0 10 0 75728853 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=881612 CPUtime=0.44
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 7721 0 0 0 43 1 0 0 25 0 10 0 75728853 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=881612 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 10 0 75728853 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 10 0 75728853 902770688 18514 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 886756

[startup+3.10692 s]
/proc/loadavg: 1.07 1.06 1.07 2/47 9409
/proc/meminfo: memFree=463560/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=881612 CPUtime=3.02
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 73764 0 1 0 274 28 0 0 25 0 10 0 75728846 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220403 70627 1743 10 0 217494 0
[pid=9400/tid=9401] ppid=9388 vsize=881612 CPUtime=1.79
/proc/9400/task/9401/stat : 9401 (java) R 9388 9386 29493 34817 29493 4202560 50067 0 1 0 157 22 0 0 25 0 10 0 75728847 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4094870794 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=881612 CPUtime=0.28
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 12832 0 0 0 26 2 0 0 16 0 10 0 75728849 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 10 0 75728850 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 10 0 75728850 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 10 0 75728853 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=881612 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 10 0 75728853 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=881612 CPUtime=0.61
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 7744 0 0 0 60 1 0 0 15 0 10 0 75728853 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=881612 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 10 0 75728853 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=881612 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 10 0 75728853 902770688 70627 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 886756

[startup+6.30783 s]
/proc/loadavg: 1.22 1.09 1.08 3/47 9409
/proc/meminfo: memFree=314640/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=882380 CPUtime=6.19
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 88686 0 1 0 586 33 0 0 25 0 11 0 75728846 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220595 84167 1778 10 0 217686 0
[pid=9400/tid=9401] ppid=9388 vsize=882380 CPUtime=3.05
/proc/9400/task/9401/stat : 9401 (java) R 9388 9386 29493 34817 29493 4202560 50258 0 1 0 283 22 0 0 25 0 11 0 75728847 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4095891216 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=882380 CPUtime=0.6
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 25889 0 0 0 53 7 0 0 16 0 11 0 75728849 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 11 0 75728850 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 11 0 75728850 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=882380 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=882380 CPUtime=2.21
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 9414 0 0 0 219 2 0 0 15 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=882380 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 887524

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

[startup+6.40787 s]
/proc/loadavg: 1.22 1.09 1.08 3/47 9409
/proc/meminfo: memFree=314640/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=882380 CPUtime=6.29
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 88686 0 1 0 596 33 0 0 25 0 11 0 75728846 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220595 84167 1778 10 0 217686 0
[pid=9400/tid=9401] ppid=9388 vsize=882380 CPUtime=3.15
/proc/9400/task/9401/stat : 9401 (java) R 9388 9386 29493 34817 29493 4202560 50258 0 1 0 293 22 0 0 25 0 11 0 75728847 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4095882040 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=882380 CPUtime=0.6
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 25889 0 0 0 53 7 0 0 16 0 11 0 75728849 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 11 0 75728850 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 11 0 75728850 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=882380 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=882380 CPUtime=2.21
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 9414 0 0 0 219 2 0 0 15 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=882380 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=882380 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 11 0 75728853 903557120 84167 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 887524

[startup+7.20304 s]
/proc/loadavg: 1.22 1.09 1.08 2/48 9410
/proc/meminfo: memFree=314392/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=882704 CPUtime=7
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 88714 0 1 0 666 34 0 0 25 0 12 0 75728846 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220676 84195 1779 10 0 217767 0
[pid=9400/tid=9401] ppid=9388 vsize=882704 CPUtime=3.69
/proc/9400/task/9401/stat : 9401 (java) S 9388 9386 29493 34817 29493 4202560 50266 0 1 0 347 22 0 0 25 0 12 0 75728847 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=882704 CPUtime=0.61
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 25889 0 0 0 54 7 0 0 15 0 12 0 75728849 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=882704 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=882704 CPUtime=2.36
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 9429 0 0 0 234 2 0 0 15 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=882704 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9410] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9410/stat : 9410 (java) S 9388 9386 29493 34817 29493 4202560 4 0 0 0 0 0 0 0 25 0 12 0 75729407 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 7.02
Current children cumulated vsize (KiB) 887848

[startup+7.60711 s]
/proc/loadavg: 1.22 1.09 1.08 2/48 9410
/proc/meminfo: memFree=314392/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=882704 CPUtime=7
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 88714 0 1 0 666 34 0 0 25 0 12 0 75728846 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220676 84195 1779 10 0 217767 0
[pid=9400/tid=9401] ppid=9388 vsize=882704 CPUtime=3.69
/proc/9400/task/9401/stat : 9401 (java) S 9388 9386 29493 34817 29493 4202560 50266 0 1 0 347 22 0 0 25 0 12 0 75728847 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=882704 CPUtime=0.61
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 25889 0 0 0 54 7 0 0 15 0 12 0 75728849 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=882704 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=882704 CPUtime=2.36
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 9429 0 0 0 234 2 0 0 15 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=882704 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 12 0 75728853 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9410] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9410/stat : 9410 (java) S 9388 9386 29493 34817 29493 4202560 4 0 0 0 0 0 0 0 25 0 12 0 75729407 903888896 84195 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 7.02
Current children cumulated vsize (KiB) 887848

[startup+7.80716 s]
/proc/loadavg: 1.22 1.09 1.08 2/49 9411
/proc/meminfo: memFree=314260/1048576 swapFree=0/0
[pid=9386] ppid=9385 vsize=2572 CPUtime=0
/proc/9386/stat : 9386 (p2cudf-paranoid) S 9385 9386 29493 34817 29493 4202496 375 0 0 0 0 0 0 0 25 0 1 0 75728841 2633728 271 1283457024 134512640 135304128 4289451184 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9386/statm: 643 271 230 194 0 30 0
[pid=9388] ppid=9386 vsize=2572 CPUtime=0.02
/proc/9388/stat : 9388 (p2cudf) S 9386 9386 29493 34817 29493 4202496 392 3003 0 1 0 0 0 2 25 0 1 0 75728841 2633728 280 1283457024 134512640 135304128 4290579920 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9388/statm: 643 280 239 194 0 30 0
[pid=9400] ppid=9388 vsize=882704 CPUtime=7.19
/proc/9400/stat : 9400 (java) S 9388 9386 29493 34817 29493 4202496 88725 0 1 0 680 39 0 0 25 0 12 0 75728846 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/9400/statm: 220676 84206 1779 10 0 217767 0
[pid=9400/tid=9401] ppid=9388 vsize=882704 CPUtime=3.69
/proc/9400/task/9401/stat : 9401 (java) S 9388 9386 29493 34817 29493 4202560 50266 0 1 0 347 22 0 0 25 0 12 0 75728847 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9402] ppid=9388 vsize=882704 CPUtime=0.61
/proc/9400/task/9402/stat : 9402 (java) S 9388 9386 29493 34817 29493 4202560 25889 0 0 0 54 7 0 0 16 0 12 0 75728849 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 0 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9403] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9403/stat : 9403 (java) S 9388 9386 29493 34817 29493 4202560 9 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9404] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9404/stat : 9404 (java) S 9388 9386 29493 34817 29493 4202560 6 0 0 0 0 0 0 0 18 0 12 0 75728850 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9405] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9405/stat : 9405 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 0 0 0 25 0 12 0 75728853 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9406] ppid=9388 vsize=882704 CPUtime=0.3
/proc/9400/task/9406/stat : 9406 (java) S 9388 9386 29493 34817 29493 4202560 2045 0 0 0 30 0 0 0 21 0 12 0 75728853 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9407] ppid=9388 vsize=882704 CPUtime=2.41
/proc/9400/task/9407/stat : 9407 (java) S 9388 9386 29493 34817 29493 4202560 9438 0 0 0 239 2 0 0 15 0 12 0 75728853 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9408] ppid=9388 vsize=882704 CPUtime=0.01
/proc/9400/task/9408/stat : 9408 (java) S 9388 9386 29493 34817 29493 4202560 1 0 0 0 0 1 0 0 25 0 12 0 75728853 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9409] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9409/stat : 9409 (java) S 9388 9386 29493 34817 29493 4202560 2 0 0 0 0 0 0 0 15 0 12 0 75728853 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9410] ppid=9388 vsize=882704 CPUtime=0
/proc/9400/task/9410/stat : 9410 (java) S 9388 9386 29493 34817 29493 4202560 4 0 0 0 0 0 0 0 25 0 12 0 75729407 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 18446612132467745728 0 0 -1 0 0 0 0
[pid=9400/tid=9411] ppid=9388 vsize=882704 CPUtime=0.14
/proc/9400/task/9411/stat : 9411 (java) R 9388 9386 29493 34817 29493 4202560 7 0 0 0 9 5 0 0 21 0 12 0 75729552 903888896 84206 1283457024 134512640 134550932 4291069152 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 7.21
Current children cumulated vsize (KiB) 887848

Child status: 0
Real time (s): 7.91002
CPU time (s): 7.26845
CPU user time (s): 6.80442
CPU system time (s): 0.464029
CPU usage (%): 91.8892
Max. virtual memory (cumulated for all children) (KiB): 890188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.80443
system time used= 0.464029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 92517
page faults= 2
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 917
involuntary context switches= 911

runsolver used 0.008 second user time and 0 second system time

The end