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/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/5698a62c-c731-11df-9bb9-00163e3d3b7c.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.45 1.45 1.26 4/36 22764
/proc/meminfo: memFree=317152/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=3712 CPUtime=0.01
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 409 0 0 0 1 0 0 0 25 0 1 0 11159610 3801088 338 1283457024 134512640 134752139 4292954080 18446744073709551615 134695260 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 928 338 286 59 0 92 0

[startup+0.134027 s]
/proc/loadavg: 1.45 1.45 1.26 4/36 22764
/proc/meminfo: memFree=317152/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=8216 CPUtime=0.13
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 1557 0 0 0 13 0 0 0 25 0 1 0 11159610 8413184 1486 1283457024 134512640 134752139 4292954080 18446744073709551615 134682008 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 2054 1486 286 59 0 1218 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10788

[startup+0.204036 s]
/proc/loadavg: 1.45 1.45 1.26 4/36 22764
/proc/meminfo: memFree=317152/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=10328 CPUtime=0.2
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 2088 0 0 0 20 0 0 0 25 0 1 0 11159610 10575872 2017 1283457024 134512640 134752139 4292954080 18446744073709551615 134540215 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 2582 2017 286 59 0 1746 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12900

[startup+0.304053 s]
/proc/loadavg: 1.45 1.45 1.26 4/36 22764
/proc/meminfo: memFree=317152/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=13084 CPUtime=0.3
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 2774 0 0 0 30 0 0 0 25 0 1 0 11159610 13398016 2703 1283457024 134512640 134752139 4292954080 18446744073709551615 134682079 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 3271 2703 286 59 0 2435 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15656

[startup+0.70412 s]
/proc/loadavg: 1.45 1.45 1.26 4/36 22764
/proc/meminfo: memFree=317152/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=23064 CPUtime=0.71
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 5270 0 0 0 67 4 0 0 25 0 1 0 11159610 23617536 5199 1283457024 134512640 134752139 4292954080 18446744073709551615 134706197 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 5766 5199 286 59 0 4930 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 25636

[startup+1.50426 s]
/proc/loadavg: 1.42 1.44 1.26 2/37 22766
/proc/meminfo: memFree=287132/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47708 CPUtime=1.5
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 11561 0 0 0 140 10 0 0 25 0 1 0 11159610 48852992 11175 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 11927 11175 321 59 0 11091 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 50280

[startup+3.10466 s]
/proc/loadavg: 1.42 1.44 1.26 2/39 22768
/proc/meminfo: memFree=259200/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47708 CPUtime=1.65
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11565 0 0 0 151 14 0 0 25 0 1 0 11159610 48852992 11178 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11927 11178 324 59 0 11091 0
[pid=22767] ppid=22764 vsize=1668 CPUtime=0
/proc/22767/stat : 22767 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 11159775 1708032 123 1283457024 134512640 134593992 4287761344 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22767/statm: 417 123 108 20 0 44 0
[pid=22768] ppid=22767 vsize=33512 CPUtime=1.43
/proc/22768/stat : 22768 (minisatp_32) R 22767 22763 4778 34817 4778 4202496 8407 0 0 0 122 21 0 0 25 0 1 0 11159777 34316288 7362 1283457024 134512640 135413687 4294763152 18446744073709551615 134698776 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22768/statm: 8378 7362 89 220 0 8156 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 85460

[startup+6.30677 s]
/proc/loadavg: 1.42 1.44 1.26 2/39 22770
/proc/meminfo: memFree=262060/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47712 CPUtime=5.11
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11642 27387 0 0 164 34 282 31 18 0 1 0 11159610 48857088 11187 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11928 11187 332 59 0 11092 0
[pid=22769] ppid=22764 vsize=1668 CPUtime=0.01
/proc/22769/stat : 22769 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 11160122 1708032 123 1283457024 134512640 134593992 4293513536 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22769/statm: 417 123 108 20 0 44 0
[pid=22770] ppid=22769 vsize=30144 CPUtime=1.17
/proc/22770/stat : 22770 (minisatp_32) R 22769 22763 4778 34817 4778 4202496 6878 0 0 0 115 2 0 0 24 0 1 0 11160123 30867456 6201 1283457024 134512640 135413687 4293519712 18446744073709551615 134649048 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22770/statm: 7536 6201 85 220 0 7314 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 82096

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

[startup+6.40439 s]
/proc/loadavg: 1.42 1.44 1.26 2/39 22770
/proc/meminfo: memFree=262060/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47712 CPUtime=5.11
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11642 27387 0 0 164 34 282 31 18 0 1 0 11159610 48857088 11187 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11928 11187 332 59 0 11092 0
[pid=22769] ppid=22764 vsize=1668 CPUtime=0.01
/proc/22769/stat : 22769 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 11160122 1708032 123 1283457024 134512640 134593992 4293513536 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22769/statm: 417 123 108 20 0 44 0
[pid=22770] ppid=22769 vsize=30144 CPUtime=1.2
/proc/22770/stat : 22770 (minisatp_32) D 22769 22763 4778 34817 4778 4202496 6921 0 0 0 116 4 0 0 25 0 1 0 11160123 30867456 6239 1283457024 134512640 135413687 4293519712 18446744073709551615 134988446 0 0 18944 0 18446744071564252162 0 0 17 0 0 0 0
/proc/22770/statm: 7536 6239 85 220 0 7314 0
Current children cumulated CPU time (s) 6.32
Current children cumulated vsize (KiB) 82096

[startup+8.00653 s]
/proc/loadavg: 1.38 1.43 1.26 2/39 22770
/proc/meminfo: memFree=176624/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47712 CPUtime=5.11
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11642 27387 0 0 164 34 282 31 18 0 1 0 11159610 48857088 11187 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11928 11187 332 59 0 11092 0
[pid=22769] ppid=22764 vsize=1668 CPUtime=0.01
/proc/22769/stat : 22769 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 11160122 1708032 123 1283457024 134512640 134593992 4293513536 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22769/statm: 417 123 108 20 0 44 0
[pid=22770] ppid=22769 vsize=122008 CPUtime=2.66
/proc/22770/stat : 22770 (minisatp_32) R 22769 22763 4778 34817 4778 4202496 31005 0 0 0 246 20 0 0 25 0 1 0 11160123 124936192 25683 1283457024 134512640 135413687 4293519712 18446744073709551615 134688022 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22770/statm: 30502 25683 107 220 0 30280 0
Current children cumulated CPU time (s) 7.78
Current children cumulated vsize (KiB) 173960

[startup+8.80678 s]
/proc/loadavg: 1.38 1.43 1.26 2/39 22770
/proc/meminfo: memFree=167448/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47712 CPUtime=5.11
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11642 27387 0 0 164 34 282 31 18 0 1 0 11159610 48857088 11187 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11928 11187 332 59 0 11092 0
[pid=22769] ppid=22764 vsize=1668 CPUtime=0.01
/proc/22769/stat : 22769 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 11160122 1708032 123 1283457024 134512640 134593992 4293513536 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22769/statm: 417 123 108 20 0 44 0
[pid=22770] ppid=22769 vsize=112348 CPUtime=3.46
/proc/22770/stat : 22770 (minisatp_32) R 22769 22763 4778 34817 4778 4202496 34436 0 0 0 325 21 0 0 25 0 1 0 11160123 115044352 25881 1283457024 134512640 135413687 4293519712 18446744073709551615 134699051 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22770/statm: 28087 25881 107 220 0 27865 0
Current children cumulated CPU time (s) 8.58
Current children cumulated vsize (KiB) 164300

[startup+9.2069 s]
/proc/loadavg: 1.38 1.43 1.26 2/39 22770
/proc/meminfo: memFree=167448/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=47712 CPUtime=5.11
/proc/22764/stat : 22764 (packup) S 22763 22763 4778 34817 4778 4202496 11642 27387 0 0 164 34 282 31 18 0 1 0 11159610 48857088 11187 1283457024 134512640 134752139 4292954080 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/22764/statm: 11928 11187 332 59 0 11092 0
[pid=22769] ppid=22764 vsize=1668 CPUtime=0.01
/proc/22769/stat : 22769 (sh) S 22764 22763 4778 34817 4778 4202496 145 0 0 0 0 1 0 0 18 0 1 0 11160122 1708032 123 1283457024 134512640 134593992 4293513536 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/22769/statm: 417 123 108 20 0 44 0
[pid=22770] ppid=22769 vsize=108420 CPUtime=3.86
/proc/22770/stat : 22770 (minisatp_32) R 22769 22763 4778 34817 4778 4202496 36319 0 0 0 365 21 0 0 25 0 1 0 11160123 111022080 25346 1283457024 134512640 135413687 4293519712 18446744073709551615 134962843 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/22770/statm: 27105 25346 107 220 0 26883 0
Current children cumulated CPU time (s) 8.98
Current children cumulated vsize (KiB) 160372

[startup+9.40051 s]
/proc/loadavg: 1.38 1.43 1.26 2/39 22770
/proc/meminfo: memFree=167448/1048576 swapFree=0/0
[pid=22763] ppid=22762 vsize=2572 CPUtime=0
/proc/22763/stat : 22763 (packup2mp4pa-0.) S 22762 22763 4778 34817 4778 4202496 378 0 0 0 0 0 0 0 18 0 1 0 11159610 2633728 274 1283457024 134512640 135304128 4293701824 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/22763/statm: 643 274 233 194 0 30 0
[pid=22764] ppid=22763 vsize=46744 CPUtime=9.15
/proc/22764/stat : 22764 (packup) R 22763 22763 4778 34817 4778 4202496 20944 63875 0 0 168 39 654 54 18 0 1 0 11159610 47865856 10958 1283457024 134512640 134752139 4292954080 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/22764/statm: 11686 10958 345 59 0 10850 0
Current children cumulated CPU time (s) 9.15
Current children cumulated vsize (KiB) 49316

Child status: 0
Real time (s): 9.45458
CPU time (s): 9.22858
CPU user time (s): 8.27652
CPU system time (s): 0.952059
CPU usage (%): 97.6096
Max. virtual memory (cumulated for all children) (KiB): 173960

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.27652
system time used= 0.952059
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 86074
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= 15
involuntary context switches= 152

runsolver used 0.004 second user time and 0 second system time

The end