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/201108281254/packup2hy4tr-0.6/7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2hy4tr-0.6 /home/misc2010/data/2011/dudf-real//7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf /home/misc2010/tmp/201108281254/packup2hy4tr-0.6/7f80e4f0-4fe9-11e0-acd7-00163e1e087d.cudf.dudf-real.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.10 1.06 1.01 3/37 22894
/proc/meminfo: memFree=201192/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) R 22892 22893 17551 34817 17551 4202496 362 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=2572 CPUtime=0
/proc/22894/stat : 22894 (packup2hy4tr-0.) R 22893 22893 17551 34817 17551 4202560 0 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 42 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/22894/statm: 643 42 0 194 0 30 0

[startup+0.111186 s]
/proc/loadavg: 1.10 1.06 1.01 3/37 22894
/proc/meminfo: memFree=201192/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=7192 CPUtime=0.07
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 1273 0 0 0 7 0 0 0 25 0 1 0 36012212 7364608 1201 1283457024 134512640 134752139 4293144592 18446744073709551615 134695938 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 1798 1201 286 59 0 962 0
Current children cumulated CPU time (s) 0.07
Current children cumulated vsize (KiB) 9764

[startup+0.207172 s]
/proc/loadavg: 1.10 1.06 1.01 3/37 22894
/proc/meminfo: memFree=201192/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=9976 CPUtime=0.14
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 1997 0 0 0 14 0 0 0 25 0 1 0 36012212 10215424 1925 1283457024 134512640 134752139 4293144592 18446744073709551615 4157134338 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 2494 1925 286 59 0 1658 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 12548

[startup+0.307198 s]
/proc/loadavg: 1.10 1.06 1.01 3/37 22894
/proc/meminfo: memFree=201192/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=12864 CPUtime=0.23
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 2715 0 0 0 22 1 0 0 25 0 1 0 36012212 13172736 2643 1283457024 134512640 134752139 4293144592 18446744073709551615 134681733 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 3216 2643 286 59 0 2380 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 15436

[startup+0.707227 s]
/proc/loadavg: 1.10 1.06 1.01 3/37 22894
/proc/meminfo: memFree=201192/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=21904 CPUtime=0.51
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 4968 0 0 0 50 1 0 0 25 0 1 0 36012212 22429696 4896 1283457024 134512640 134752139 4293144592 18446744073709551615 4157173306 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 5476 4896 286 59 0 4640 0
Current children cumulated CPU time (s) 0.51
Current children cumulated vsize (KiB) 24476

[startup+1.50802 s]
/proc/loadavg: 1.09 1.06 1.01 2/38 22895
/proc/meminfo: memFree=153352/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35376 CPUtime=1
/proc/22894/stat : 22894 (packup) S 22893 22893 17551 34817 17551 4202496 8375 0 0 0 88 12 0 0 25 0 1 0 36012212 36225024 8184 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22894/statm: 8844 8184 324 59 0 8008 0
Current children cumulated CPU time (s) 1
Current children cumulated vsize (KiB) 37948

[startup+3.10852 s]
/proc/loadavg: 1.09 1.06 1.01 2/41 22901
/proc/meminfo: memFree=114740/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35380 CPUtime=2.9
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 8445 19991 0 0 93 15 166 16 18 0 1 0 36012212 36229120 8196 1283457024 134512640 134752139 4293144592 18446744073709551615 4158892316 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 8845 8196 332 59 0 8009 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 37952

[startup+6.30969 s]
/proc/loadavg: 1.08 1.06 1.01 2/41 22913
/proc/meminfo: memFree=130240/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35388 CPUtime=5.99
/proc/22894/stat : 22894 (packup) S 22893 22893 17551 34817 17551 4202496 8569 44659 0 0 114 43 396 46 18 0 1 0 36012212 36237312 8204 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22894/statm: 8847 8204 332 59 0 8011 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 37960

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

[startup+6.40971 s]
/proc/loadavg: 1.08 1.06 1.01 2/41 22913
/proc/meminfo: memFree=130240/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35388 CPUtime=5.99
/proc/22894/stat : 22894 (packup) S 22893 22893 17551 34817 17551 4202496 8569 44659 0 0 114 43 396 46 18 0 1 0 36012212 36237312 8204 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22894/statm: 8847 8204 332 59 0 8011 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 37960

[startup+8.01003 s]
/proc/loadavg: 1.08 1.06 1.01 2/43 22924
/proc/meminfo: memFree=88916/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35388 CPUtime=5.99
/proc/22894/stat : 22894 (packup) S 22893 22893 17551 34817 17551 4202496 8569 44659 0 0 114 43 396 46 18 0 1 0 36012212 36237312 8204 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22894/statm: 8847 8204 332 59 0 8011 0
[pid=22914] ppid=22894 vsize=1672 CPUtime=0
/proc/22914/stat : 22914 (sh) S 22894 22893 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 18 0 1 0 36012834 1712128 123 1283457024 134512640 134593992 4290977504 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22914/statm: 418 123 108 20 0 45 0
[pid=22915] ppid=22914 vsize=2572 CPUtime=0
/proc/22915/stat : 22915 (run_h) S 22914 22893 17551 34817 17551 4202496 366 610 0 0 0 0 0 0 21 0 1 0 36012834 2633728 273 1283457024 134512640 135304128 4292333632 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22915/statm: 643 273 232 194 0 30 0
[pid=22919] ppid=22915 vsize=2568 CPUtime=0.01
/proc/22919/stat : 22919 (run_scip) S 22915 22893 17551 34817 17551 4202496 391 753 0 0 0 0 1 0 22 0 1 0 36012834 2629632 268 1283457024 134512640 135304128 4293636480 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22919/statm: 642 268 228 194 0 29 0
[pid=22923] ppid=22919 vsize=72628 CPUtime=1.76
/proc/22923/stat : 22923 (scip-2.0.1.linu) R 22919 22893 17551 34817 17551 4202496 18104 0 0 0 152 24 0 0 25 0 1 0 36012835 74371072 16014 1283457024 134512640 143279753 4294136240 18446744073709551615 135922303 0 0 18944 2 0 0 0 17 0 0 0 0
/proc/22923/statm: 18157 16014 620 2141 0 16013 0
[pid=22924] ppid=22919 vsize=7192 CPUtime=0.01
/proc/22924/stat : 22924 (scip2v) S 22919 22893 17551 34817 17551 4202496 1008 0 0 0 1 0 0 0 18 0 1 0 36012848 7364608 847 1283457024 134512640 136477024 4294326832 18446744073709551615 4294960130 0 0 16800256 2 18446744071564457842 0 0 17 0 0 0 0
/proc/22924/statm: 1798 847 474 480 0 383 0
Current children cumulated CPU time (s) 7.77
Current children cumulated vsize (KiB) 124592

[startup+8.4101 s]
/proc/loadavg: 1.08 1.06 1.01 2/43 22924
/proc/meminfo: memFree=88916/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35388 CPUtime=5.99
/proc/22894/stat : 22894 (packup) S 22893 22893 17551 34817 17551 4202496 8569 44659 0 0 114 43 396 46 18 0 1 0 36012212 36237312 8204 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22894/statm: 8847 8204 332 59 0 8011 0
[pid=22914] ppid=22894 vsize=1672 CPUtime=0
/proc/22914/stat : 22914 (sh) S 22894 22893 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 18 0 1 0 36012834 1712128 123 1283457024 134512640 134593992 4290977504 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22914/statm: 418 123 108 20 0 45 0
[pid=22915] ppid=22914 vsize=2572 CPUtime=0
/proc/22915/stat : 22915 (run_h) S 22914 22893 17551 34817 17551 4202496 366 610 0 0 0 0 0 0 21 0 1 0 36012834 2633728 273 1283457024 134512640 135304128 4292333632 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22915/statm: 643 273 232 194 0 30 0
[pid=22919] ppid=22915 vsize=2568 CPUtime=0.01
/proc/22919/stat : 22919 (run_scip) S 22915 22893 17551 34817 17551 4202496 391 753 0 0 0 0 1 0 22 0 1 0 36012834 2629632 268 1283457024 134512640 135304128 4293636480 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22919/statm: 642 268 228 194 0 29 0
[pid=22923] ppid=22919 vsize=73016 CPUtime=2.16
/proc/22923/stat : 22923 (scip-2.0.1.linu) R 22919 22893 17551 34817 17551 4202496 23888 0 0 0 180 36 0 0 25 0 1 0 36012835 74768384 16122 1283457024 134512640 143279753 4294136240 18446744073709551615 4294960130 0 0 18944 2 0 0 0 17 0 0 0 0
/proc/22923/statm: 18254 16122 641 2141 0 16110 0
[pid=22924] ppid=22919 vsize=7192 CPUtime=0.01
/proc/22924/stat : 22924 (scip2v) S 22919 22893 17551 34817 17551 4202496 1009 0 0 0 1 0 0 0 18 0 1 0 36012848 7364608 848 1283457024 134512640 136477024 4294326832 18446744073709551615 4294960130 0 0 16800256 2 18446744071564457842 0 0 17 0 0 0 0
/proc/22924/statm: 1798 848 474 480 0 383 0
Current children cumulated CPU time (s) 8.17
Current children cumulated vsize (KiB) 124980

[startup+8.61012 s]
/proc/loadavg: 1.08 1.06 1.01 2/43 22924
/proc/meminfo: memFree=88916/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=35392 CPUtime=8.38
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202496 8639 72308 0 0 115 43 591 89 18 0 1 0 36012212 36241408 8218 1283457024 134512640 134752139 4293144592 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 8848 8218 345 59 0 8012 0
Current children cumulated CPU time (s) 8.38
Current children cumulated vsize (KiB) 37964

[startup+8.71024 s]
/proc/loadavg: 1.08 1.06 1.01 2/43 22924
/proc/meminfo: memFree=88916/1048576 swapFree=0/0
[pid=22893] ppid=22892 vsize=2572 CPUtime=0
/proc/22893/stat : 22893 (packup2hy4tr-0.) S 22892 22893 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 25 0 1 0 36012212 2633728 275 1283457024 134512640 135304128 4289361056 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22893/statm: 643 275 233 194 0 30 0
[pid=22894] ppid=22893 vsize=0 CPUtime=8.49
/proc/22894/stat : 22894 (packup) R 22893 22893 17551 34817 17551 4202500 16099 72308 0 0 124 45 591 89 18 0 1 0 36012212 0 0 1283457024 0 0 0 0 0 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22894/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.49
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 8.71257
CPU time (s): 8.50053
CPU user time (s): 7.15245
CPU system time (s): 1.34808
CPU usage (%): 97.5663
Max. virtual memory (cumulated for all children) (KiB): 125688

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.15245
system time used= 1.34808
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 88796
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= 13321
involuntary context switches= 13429

runsolver used 0 second user time and 0.008 second system time

The end