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/rand598.cudf.s-e-l.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/incremental/s-e-l/rand598.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand598.cudf.s-e-l.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.22 1.08 1.02 4/36 17235
/proc/meminfo: memFree=386784/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=3716 CPUtime=0.01
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 412 0 0 0 1 0 0 0 25 0 1 0 11078980 3805184 341 1283457024 134512640 134752139 4292806640 18446744073709551615 134681645 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 929 341 286 59 0 93 0

[startup+0.144181 s]
/proc/loadavg: 1.22 1.08 1.02 4/36 17235
/proc/meminfo: memFree=386784/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=9128 CPUtime=0.14
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 1786 0 0 0 14 0 0 0 25 0 1 0 11078980 9347072 1715 1283457024 134512640 134752139 4292806640 18446744073709551615 4157763130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 2282 1715 286 59 0 1446 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 11696

[startup+0.204191 s]
/proc/loadavg: 1.22 1.08 1.02 4/36 17235
/proc/meminfo: memFree=386784/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=11240 CPUtime=0.2
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 2299 0 0 0 20 0 0 0 25 0 1 0 11078980 11509760 2228 1283457024 134512640 134752139 4292806640 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 2810 2228 286 59 0 1974 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13808

[startup+0.304214 s]
/proc/loadavg: 1.22 1.08 1.02 4/36 17235
/proc/meminfo: memFree=386784/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=14408 CPUtime=0.3
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 3082 0 0 0 30 0 0 0 25 0 1 0 11078980 14753792 3011 1283457024 134512640 134752139 4292806640 18446744073709551615 4157740767 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 3602 3011 286 59 0 2766 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16976

[startup+0.704288 s]
/proc/loadavg: 1.22 1.08 1.02 4/36 17235
/proc/meminfo: memFree=386784/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=25164 CPUtime=0.7
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 5789 0 0 0 67 3 0 0 25 0 1 0 11078980 25767936 5718 1283457024 134512640 134752139 4292806640 18446744073709551615 134695556 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 6291 5718 286 59 0 5455 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27732

[startup+1.50443 s]
/proc/loadavg: 1.22 1.08 1.02 2/37 17236
/proc/meminfo: memFree=350812/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=39340 CPUtime=1.2
/proc/17235/stat : 17235 (packup) S 17234 17234 4778 34817 4778 4202496 9452 0 0 0 105 15 0 0 25 0 1 0 11078980 40284160 9137 1283457024 134512640 134752139 4292806640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17235/statm: 9835 9137 324 59 0 8999 0
Current children cumulated CPU time (s) 1.2
Current children cumulated vsize (KiB) 41908

[startup+3.10472 s]
/proc/loadavg: 1.20 1.08 1.02 2/39 17238
/proc/meminfo: memFree=330444/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=39344 CPUtime=2.73
/proc/17235/stat : 17235 (packup) S 17234 17234 4778 34817 4778 4202496 9504 9573 0 0 112 29 113 19 18 0 1 0 11078980 40288256 9146 1283457024 134512640 134752139 4292806640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17235/statm: 9836 9146 332 59 0 9000 0
Current children cumulated CPU time (s) 2.73
Current children cumulated vsize (KiB) 41912

[startup+6.30528 s]
/proc/loadavg: 1.20 1.08 1.02 2/39 17241
/proc/meminfo: memFree=284936/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=39344 CPUtime=2.73
/proc/17235/stat : 17235 (packup) S 17234 17234 4778 34817 4778 4202496 9504 9573 0 0 112 29 113 19 18 0 1 0 11078980 40288256 9146 1283457024 134512640 134752139 4292806640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17235/statm: 9836 9146 332 59 0 9000 0
[pid=17239] ppid=17235 vsize=1672 CPUtime=0
/proc/17239/stat : 17239 (sh) S 17235 17234 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11079255 1712128 124 1283457024 134512640 134593992 4287378288 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17239/statm: 418 124 108 20 0 45 0
[pid=17240] ppid=17239 vsize=123380 CPUtime=3.55
/proc/17240/stat : 17240 (minisatp_32) R 17239 17234 4778 34817 4778 4202496 34830 0 0 0 329 26 0 0 25 0 1 0 11079255 126341120 26153 1283457024 134512640 135413687 4287409040 18446744073709551615 134699252 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17240/statm: 30845 26153 107 220 0 30623 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 166964

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

[startup+6.40534 s]
/proc/loadavg: 1.20 1.08 1.02 2/39 17241
/proc/meminfo: memFree=284936/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=39344 CPUtime=2.73
/proc/17235/stat : 17235 (packup) S 17234 17234 4778 34817 4778 4202496 9504 9573 0 0 112 29 113 19 18 0 1 0 11078980 40288256 9146 1283457024 134512640 134752139 4292806640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17235/statm: 9836 9146 332 59 0 9000 0
[pid=17239] ppid=17235 vsize=1672 CPUtime=0
/proc/17239/stat : 17239 (sh) S 17235 17234 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11079255 1712128 124 1283457024 134512640 134593992 4287378288 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17239/statm: 418 124 108 20 0 45 0
[pid=17240] ppid=17239 vsize=123512 CPUtime=3.65
/proc/17240/stat : 17240 (minisatp_32) R 17239 17234 4778 34817 4778 4202496 34877 0 0 0 339 26 0 0 25 0 1 0 11079255 126476288 26197 1283457024 134512640 135413687 4287409040 18446744073709551615 134698564 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17240/statm: 30878 26197 107 220 0 30656 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 167096

[startup+6.60544 s]
/proc/loadavg: 1.20 1.08 1.02 2/39 17241
/proc/meminfo: memFree=254184/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=39344 CPUtime=2.73
/proc/17235/stat : 17235 (packup) S 17234 17234 4778 34817 4778 4202496 9504 9573 0 0 112 29 113 19 18 0 1 0 11078980 40288256 9146 1283457024 134512640 134752139 4292806640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/17235/statm: 9836 9146 332 59 0 9000 0
[pid=17239] ppid=17235 vsize=1672 CPUtime=0
/proc/17239/stat : 17239 (sh) S 17235 17234 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11079255 1712128 124 1283457024 134512640 134593992 4287378288 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/17239/statm: 418 124 108 20 0 45 0
[pid=17240] ppid=17239 vsize=107488 CPUtime=3.85
/proc/17240/stat : 17240 (minisatp_32) R 17239 17234 4778 34817 4778 4202496 36416 0 0 0 359 26 0 0 25 0 1 0 11079255 110067712 23750 1283457024 134512640 135413687 4287409040 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/17240/statm: 26872 23750 117 220 0 26650 0
Current children cumulated CPU time (s) 6.58
Current children cumulated vsize (KiB) 151072

[startup+6.70548 s]
/proc/loadavg: 1.20 1.08 1.02 2/39 17241
/proc/meminfo: memFree=254184/1048576 swapFree=0/0
[pid=17234] ppid=17233 vsize=2568 CPUtime=0
/proc/17234/stat : 17234 (packup2mp4pa-0.) S 17233 17234 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11078980 2629632 273 1283457024 134512640 135304128 4290706976 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/17234/statm: 642 273 233 194 0 29 0
[pid=17235] ppid=17234 vsize=37020 CPUtime=6.69
/proc/17235/stat : 17235 (packup) R 17234 17234 4778 34817 4778 4202496 17462 46139 0 0 116 31 476 46 18 0 1 0 11078980 37908480 8721 1283457024 134512640 134752139 4292806640 18446744073709551615 4157736192 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/17235/statm: 9255 8721 345 59 0 8419 0
Current children cumulated CPU time (s) 6.69
Current children cumulated vsize (KiB) 39588

Child status: 0
Real time (s): 6.72004
CPU time (s): 6.71642
CPU user time (s): 5.93237
CPU system time (s): 0.784049
CPU usage (%): 99.9462
Max. virtual memory (cumulated for all children) (KiB): 174172

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.93237
system time used= 0.784049
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 64365
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= 124

runsolver used 0 second user time and 0 second system time

The end