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/201108251442/packup2mp4pa-0.6/rand83.cudf.dudf-random.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-random//rand83.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand83.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.62 1.47 1.26 5/34 22586
/proc/meminfo: memFree=339772/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=4104 CPUtime=0.01
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 500 0 0 0 0 1 0 0 25 0 1 0 11155561 4202496 429 1283457024 134512640 134752139 4294549904 18446744073709551615 134681682 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 1026 429 286 59 0 190 0

[startup+0.172277 s]
/proc/loadavg: 1.62 1.47 1.26 5/34 22586
/proc/meminfo: memFree=339772/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=9028 CPUtime=0.17
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 1757 0 0 0 16 1 0 0 25 0 1 0 11155561 9244672 1686 1283457024 134512640 134752139 4294549904 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 2257 1686 286 59 0 1421 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11600

[startup+0.20229 s]
/proc/loadavg: 1.62 1.47 1.26 5/34 22586
/proc/meminfo: memFree=339772/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=9952 CPUtime=0.21
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 1975 0 0 0 20 1 0 0 25 0 1 0 11155561 10190848 1904 1283457024 134512640 134752139 4294549904 18446744073709551615 134706187 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 2488 1904 286 59 0 1652 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12524

[startup+0.312321 s]
/proc/loadavg: 1.62 1.47 1.26 5/34 22586
/proc/meminfo: memFree=339772/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=12972 CPUtime=0.31
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 2719 0 0 0 30 1 0 0 25 0 1 0 11155561 13283328 2648 1283457024 134512640 134752139 4294549904 18446744073709551615 4157347247 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 3243 2648 286 59 0 2407 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15544

[startup+0.712533 s]
/proc/loadavg: 1.62 1.47 1.26 5/34 22586
/proc/meminfo: memFree=339772/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=22672 CPUtime=0.71
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 5142 0 0 0 69 2 0 0 25 0 1 0 11155561 23216128 5071 1283457024 134512640 134752139 4294549904 18446744073709551615 4159252288 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 5668 5071 286 59 0 4832 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 25244

[startup+1.51279 s]
/proc/loadavg: 1.62 1.47 1.26 2/35 22587
/proc/meminfo: memFree=312532/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=45996 CPUtime=1.51
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 11062 0 0 0 148 3 0 0 25 0 1 0 11155561 47099904 10942 1283457024 134512640 134752139 4294549904 18446744073709551615 134668255 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 11499 10942 316 59 0 10663 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 48568

[startup+3.11323 s]
/proc/loadavg: 1.57 1.47 1.26 2/37 22589
/proc/meminfo: memFree=283732/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51044 CPUtime=1.87
/proc/22586/stat : 22586 (packup) S 22585 22585 4778 34817 4778 4202496 12332 0 0 0 168 19 0 0 25 0 1 0 11155561 52269056 12009 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22586/statm: 12761 12009 324 59 0 11925 0
[pid=22588] ppid=22586 vsize=1676 CPUtime=0
/proc/22588/stat : 22588 (sh) S 22586 22585 4778 34817 4778 4202496 148 0 0 0 0 0 0 0 25 0 1 0 11155748 1716224 124 1283457024 134512640 134593992 4288697520 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22588/statm: 419 124 108 20 0 46 0
[pid=22589] ppid=22588 vsize=29756 CPUtime=1.22
/proc/22589/stat : 22589 (minisatp_32) R 22588 22585 4778 34817 4778 4202496 7069 0 0 0 112 10 0 0 25 0 1 0 11155750 30470144 6285 1283457024 134512640 135413687 4293431632 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22589/statm: 7439 6285 85 220 0 7217 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 85048

[startup+6.31392 s]
/proc/loadavg: 1.57 1.47 1.26 2/37 22591
/proc/meminfo: memFree=281996/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51048 CPUtime=5.12
/proc/22586/stat : 22586 (packup) S 22585 22585 4778 34817 4778 4202496 12406 26104 0 0 188 29 276 19 18 0 1 0 11155561 52273152 12018 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22586/statm: 12762 12018 332 59 0 11926 0
[pid=22590] ppid=22586 vsize=1672 CPUtime=0.01
/proc/22590/stat : 22590 (sh) S 22586 22585 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 11156075 1712128 123 1283457024 134512640 134593992 4288519296 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22590/statm: 418 123 108 20 0 45 0
[pid=22591] ppid=22590 vsize=28868 CPUtime=1.16
/proc/22591/stat : 22591 (minisatp_32) R 22590 22585 4778 34817 4778 4202496 6570 0 0 0 113 3 0 0 24 0 1 0 11156076 29560832 5965 1283457024 134512640 135413687 4289707456 18446744073709551615 134656158 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22591/statm: 7217 5965 85 220 0 6995 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 84160

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

[startup+6.40393 s]
/proc/loadavg: 1.57 1.47 1.26 2/37 22591
/proc/meminfo: memFree=281996/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51048 CPUtime=5.12
/proc/22586/stat : 22586 (packup) S 22585 22585 4778 34817 4778 4202496 12406 26104 0 0 188 29 276 19 18 0 1 0 11155561 52273152 12018 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22586/statm: 12762 12018 332 59 0 11926 0
[pid=22590] ppid=22586 vsize=1672 CPUtime=0.01
/proc/22590/stat : 22590 (sh) S 22586 22585 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 11156075 1712128 123 1283457024 134512640 134593992 4288519296 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22590/statm: 418 123 108 20 0 45 0
[pid=22591] ppid=22590 vsize=29512 CPUtime=1.26
/proc/22591/stat : 22591 (minisatp_32) R 22590 22585 4778 34817 4778 4202496 6906 0 0 0 114 12 0 0 25 0 1 0 11156076 30220288 6213 1283457024 134512640 135413687 4289707456 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22591/statm: 7378 6213 85 220 0 7156 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 84804

[startup+7.20407 s]
/proc/loadavg: 1.52 1.46 1.26 2/37 22591
/proc/meminfo: memFree=260552/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51048 CPUtime=5.12
/proc/22586/stat : 22586 (packup) S 22585 22585 4778 34817 4778 4202496 12406 26104 0 0 188 29 276 19 18 0 1 0 11155561 52273152 12018 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22586/statm: 12762 12018 332 59 0 11926 0
[pid=22590] ppid=22586 vsize=1672 CPUtime=0.01
/proc/22590/stat : 22590 (sh) S 22586 22585 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 11156075 1712128 123 1283457024 134512640 134593992 4288519296 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22590/statm: 418 123 108 20 0 45 0
[pid=22591] ppid=22590 vsize=88964 CPUtime=2.05
/proc/22591/stat : 22591 (minisatp_32) R 22590 22585 4778 34817 4778 4202496 23898 0 0 0 184 21 0 0 25 0 1 0 11156076 91099136 18888 1283457024 134512640 135413687 4289707456 18446744073709551615 134689947 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22591/statm: 22241 18888 108 220 0 22019 0
Current children cumulated CPU time (s) 7.18
Current children cumulated vsize (KiB) 144256

[startup+8.00423 s]
/proc/loadavg: 1.52 1.46 1.26 2/37 22591
/proc/meminfo: memFree=210208/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51048 CPUtime=5.12
/proc/22586/stat : 22586 (packup) S 22585 22585 4778 34817 4778 4202496 12406 26104 0 0 188 29 276 19 18 0 1 0 11155561 52273152 12018 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22586/statm: 12762 12018 332 59 0 11926 0
[pid=22590] ppid=22586 vsize=1672 CPUtime=0.01
/proc/22590/stat : 22590 (sh) S 22586 22585 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 18 0 1 0 11156075 1712128 123 1283457024 134512640 134593992 4288519296 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22590/statm: 418 123 108 20 0 45 0
[pid=22591] ppid=22590 vsize=98600 CPUtime=2.85
/proc/22591/stat : 22591 (minisatp_32) R 22590 22585 4778 34817 4778 4202496 28475 0 0 0 262 23 0 0 25 0 1 0 11156076 100966400 20930 1283457024 134512640 135413687 4289707456 18446744073709551615 134698544 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22591/statm: 24650 20930 108 220 0 24428 0
Current children cumulated CPU time (s) 7.98
Current children cumulated vsize (KiB) 153892

[startup+8.40428 s]
/proc/loadavg: 1.52 1.46 1.26 2/37 22591
/proc/meminfo: memFree=210208/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=51052 CPUtime=8.38
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 12489 56240 0 0 188 30 575 45 18 0 1 0 11155561 52277248 12032 1283457024 134512640 134752139 4294549904 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 12763 12032 345 59 0 11927 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 53624

[startup+8.50432 s]
/proc/loadavg: 1.52 1.46 1.26 2/37 22591
/proc/meminfo: memFree=210208/1048576 swapFree=0/0
[pid=22585] ppid=22584 vsize=2572 CPUtime=0
/proc/22585/stat : 22585 (packup2mp4pa-0.) S 22584 22585 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11155561 2633728 275 1283457024 134512640 135304128 4292265888 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22585/statm: 643 275 233 194 0 30 0
[pid=22586] ppid=22585 vsize=50080 CPUtime=8.49
/proc/22586/stat : 22586 (packup) R 22585 22585 4778 34817 4778 4202496 22580 56240 0 0 196 33 575 45 18 0 1 0 11155561 51281920 11789 1283457024 134512640 134752139 4294549904 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22586/statm: 12520 11789 345 59 0 11684 0
Current children cumulated CPU time (s) 8.49
Current children cumulated vsize (KiB) 52652

Child status: 0
Real time (s): 8.53926
CPU time (s): 8.52853
CPU user time (s): 7.73248
CPU system time (s): 0.796049
CPU usage (%): 99.8743
Max. virtual memory (cumulated for all children) (KiB): 160968

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.73248
system time used= 0.796049
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 80082
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= 11
involuntary context switches= 150

runsolver used 0 second user time and 0 second system time

The end