This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

View | Details | Raw Unified | Return to bug 269576
Collapse All | Expand All

(-)a/core.startup/src/org/netbeans/core/startup/logging/PrintStreamLogger.java (-9 / +101 lines)
Lines 51-58 Link Here
51
/** a stream to delegate to logging.
51
/** a stream to delegate to logging.
52
 */
52
 */
53
public final class PrintStreamLogger extends PrintStream implements Runnable {
53
public final class PrintStreamLogger extends PrintStream implements Runnable {
54
    /**
55
     * Threshold of buffered data before the background thread starts to flush it to the logger.
56
     */
57
    // not private bcs of test
58
    static final int BUFFER_THRESHOLD = 2 * 1024 * 1024;
59
    
60
    /**
61
     * Minimum capacity, does not shring below this size.
62
     */
63
    private static final int BUFFER_MIN_CAPACITY = 1024 * 1024;
64
    
65
    /**
66
     * Time after which the buffer shrinks/is recycled, if not adequately used.
67
     */
68
    // not private bcs of test
69
    static final int BUFFER_SHRINK_TIME = 10 * 1000;
70
    
71
    /**
72
     * Ratio of required buffer usage. If the buffer is used up to less than
73
     * 1/n, the builder will be recycled on the next flush.
74
     */
75
    private static final int BUFFER_CAPACITY_DIV = 5;
76
    
54
    private Logger log;
77
    private Logger log;
55
    private final StringBuilder sb = new StringBuilder();
78
    
79
    @SuppressWarnings("RedundantStringConstructorCall") // prevent interning
80
    private final Object lock = new String("lock"); // NOI18N
81
    
82
    // @GuardedBy(lock)
83
    private StringBuilder sb = new StringBuilder();
84
85
    // @GuardedBy(lock)
86
    private int bufferTop = 0;
87
    
88
    /**
89
     * Maximum useful buffer size at the time of flush
90
     * @GuardedBy(lock)
91
     */
92
    private int maxBufferSize;
93
    
94
    /**
95
     * Last time the buffer was checked/shrinked
96
     * @GuardedBy(lock)
97
     */
98
    private long lastCleanupTime;
99
    
56
    private static RequestProcessor RP = new RequestProcessor("StdErr Flush");
100
    private static RequestProcessor RP = new RequestProcessor("StdErr Flush");
57
    private RequestProcessor.Task flush = RP.create(this, true);
101
    private RequestProcessor.Task flush = RP.create(this, true);
58
102
Lines 93-102 Link Here
93
        if (RP.isRequestProcessorThread()) {
137
        if (RP.isRequestProcessorThread()) {
94
            return;
138
            return;
95
        }
139
        }
96
        synchronized (sb) {
140
        synchronized (lock) {
97
            sb.append((char) b);
141
            sb.append((char) b);
142
            checkFlush();
98
        }
143
        }
99
        checkFlush();
100
    }
144
    }
101
145
102
    @Override
146
    @Override
Lines 104-113 Link Here
104
        if (NbLogging.DEBUG != null && !NbLogging.wantsMessage(s)) {
148
        if (NbLogging.DEBUG != null && !NbLogging.wantsMessage(s)) {
105
            new Exception().printStackTrace(NbLogging.DEBUG);
149
            new Exception().printStackTrace(NbLogging.DEBUG);
106
        }
150
        }
107
        synchronized (sb) {
151
        synchronized (lock) {
108
            sb.append(s);
152
            sb.append(s);
153
            checkFlush();
109
        }
154
        }
110
        checkFlush();
111
    }
155
    }
112
156
113
    @Override
157
    @Override
Lines 125-131 Link Here
125
    @Override
169
    @Override
126
    public void flush() {
170
    public void flush() {
127
        boolean empty;
171
        boolean empty;
128
        synchronized (sb) {
172
        synchronized (lock) {
129
            empty = sb.length() == 0;
173
            empty = sb.length() == 0;
130
        }
174
        }
131
        if (!empty) {
175
        if (!empty) {
Lines 142-149 Link Here
142
186
143
    private void checkFlush() {
187
    private void checkFlush() {
144
        //if (DEBUG != null) DEBUG.println("checking flush; buffer: " + sb); // NOI18N
188
        //if (DEBUG != null) DEBUG.println("checking flush; buffer: " + sb); // NOI18N
189
        boolean immediate = sb.length() - bufferTop > BUFFER_THRESHOLD;
145
        try {
190
        try {
146
            flush.schedule(100);
191
            flush.schedule(immediate ? 0 : 100);
147
        } catch (IllegalStateException ex) {
192
        } catch (IllegalStateException ex) {
148
            /* can happen during shutdown:
193
            /* can happen during shutdown:
149
            Nested Exception is:
194
            Nested Exception is:
Lines 169-194 Link Here
169
             */
214
             */
170
        }
215
        }
171
    }
216
    }
217
    
218
    private final RequestProcessor.Task cleanupTask = RP.create(new Runnable() {
219
        public void run() {
220
            synchronized (lock) {
221
                maybeFreeBuffer();
222
            }
223
        }
224
    });
225
    
226
    /**
227
     * Conditionally shrinks the buffer. Called synchronously from flusher, and 
228
     * scheduled (by the flusher) to cover the case logging ends within BUFFER_SHRINK_TIME
229
     * and no more data comes.
230
     * <p/>
231
     * The intention is to recycle the buffer, if it was not filled at least to 1/BUFFER_CAPACITY_DIV
232
     * of its capacity during the last BUFFER_SHRINK_TIME millis.
233
     */
234
    private void maybeFreeBuffer() {
235
        int c = sb.capacity();
236
        long t = System.currentTimeMillis();
237
        if (t - lastCleanupTime > BUFFER_SHRINK_TIME) {
238
            if (c > BUFFER_MIN_CAPACITY &&
239
                c / BUFFER_CAPACITY_DIV > maxBufferSize) {
240
                // recycle the buffer, reclaim potential memory
241
                sb = new StringBuilder(sb);
242
            }
243
            maxBufferSize = sb.length();
244
            lastCleanupTime = t;
245
        }
246
    }
172
247
173
    public void run() {
248
    public void run() {
174
        for (;;) {
249
        for (;;) {
175
            String toLog;
250
            String toLog;
176
            synchronized (sb) {
251
            synchronized (lock) {
177
                if (sb.length() == 0) {
252
                if (sb.length() == 0) {
178
                    break;
253
                    break;
179
                }
254
                }
255
                maxBufferSize = Math.max(maxBufferSize, sb.length());
180
                int last = -1;
256
                int last = -1;
181
                for (int i = sb.length() - 1; i >= 0; i--) {
257
                for (int i = sb.length() - 1; i >= bufferTop; i--) {
182
                    if (sb.charAt(i) == '\n') {
258
                    if (sb.charAt(i) == '\n') {
183
                        last = i;
259
                        last = i;
184
                        break;
260
                        break;
185
                    }
261
                    }
186
                }
262
                }
187
                if (last == -1) {
263
                if (last == -1) {
264
                    // no \n in the buffer
265
                    bufferTop = sb.length();
188
                    break;
266
                    break;
189
                }
267
                }
190
                toLog = sb.substring(0, last + 1);
268
                toLog = sb.substring(0, last + 1);
269
                // the remained does not contain a newline
270
                // PEDNING: perf: circular buffer should be used here. 
191
                sb.delete(0, last + 1);
271
                sb.delete(0, last + 1);
272
                bufferTop = sb.length();
273
                // attempt to free the buffer
274
                maybeFreeBuffer();
275
                // schedule for the case that data stops coming in
276
                cleanupTask.schedule(BUFFER_SHRINK_TIME);
277
                lock.notifyAll();
192
            }
278
            }
193
            int begLine = 0;
279
            int begLine = 0;
194
            while (begLine < toLog.length()) {
280
            while (begLine < toLog.length()) {
Lines 199-202 Link Here
199
        }
285
        }
200
    }
286
    }
201
    
287
    
288
    // Testing only
289
    int[] bufferSizes() {
290
        synchronized (lock) {
291
            return new int[] { sb.length(), sb.capacity() };
292
        }
293
    }
202
} // end of LgStream
294
} // end of LgStream
(-)a/core.startup/test/unit/src/org/netbeans/core/startup/logging/PrintStreamLoggerTest.java (+160 lines)
Line 0 Link Here
1
/*
2
 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS HEADER.
3
 *
4
 * Copyright 2017 Oracle and/or its affiliates. All rights reserved.
5
 *
6
 * Oracle and Java are registered trademarks of Oracle and/or its affiliates.
7
 * Other names may be trademarks of their respective owners.
8
 *
9
 * The contents of this file are subject to the terms of either the GNU
10
 * General Public License Version 2 only ("GPL") or the Common
11
 * Development and Distribution License("CDDL") (collectively, the
12
 * "License"). You may not use this file except in compliance with the
13
 * License. You can obtain a copy of the License at
14
 * http://www.netbeans.org/cddl-gplv2.html
15
 * or nbbuild/licenses/CDDL-GPL-2-CP. See the License for the
16
 * specific language governing permissions and limitations under the
17
 * License.  When distributing the software, include this License Header
18
 * Notice in each file and include the License file at
19
 * nbbuild/licenses/CDDL-GPL-2-CP.  Oracle designates this
20
 * particular file as subject to the "Classpath" exception as provided
21
 * by Oracle in the GPL Version 2 section of the License file that
22
 * accompanied this code. If applicable, add the following below the
23
 * License Header, with the fields enclosed by brackets [] replaced by
24
 * your own identifying information:
25
 * "Portions Copyrighted [year] [name of copyright owner]"
26
 *
27
 * If you wish your version of this file to be governed by only the CDDL
28
 * or only the GPL Version 2, indicate your decision by adding
29
 * "[Contributor] elects to include this software in this distribution
30
 * under the [CDDL or GPL Version 2] license." If you do not indicate a
31
 * single choice of license, a recipient has the option to distribute
32
 * your version of this file under either the CDDL, the GPL Version 2 or
33
 * to extend the choice of license to its licensees as provided above.
34
 * However, if you add GPL Version 2 code and therefore, elected the GPL
35
 * Version 2 license, then the option applies only if the new code is
36
 * made subject to such option by the copyright holder.
37
 *
38
 * Contributor(s):
39
 *
40
 * Portions Copyrighted 2017 Sun Microsystems, Inc.
41
 */
42
package org.netbeans.core.startup.logging;
43
44
import java.io.PrintStream;
45
import java.lang.reflect.Field;
46
import java.util.ArrayList;
47
import java.util.List;
48
import java.util.logging.Handler;
49
import java.util.logging.Level;
50
import java.util.logging.LogManager;
51
import java.util.logging.LogRecord;
52
import java.util.logging.Logger;
53
import static org.netbeans.core.startup.logging.PrintStreamLogger.BUFFER_SHRINK_TIME;
54
import static org.netbeans.core.startup.logging.PrintStreamLogger.BUFFER_THRESHOLD;
55
import org.netbeans.junit.NbTestCase;
56
57
/**
58
 *
59
 * @author sdedic
60
 */
61
public class PrintStreamLoggerTest extends NbTestCase {
62
    
63
    private static class LH extends Handler {
64
        List<LogRecord> records = new ArrayList<>();
65
        
66
        @Override
67
        public void publish(LogRecord record) {
68
            records.add(record);
69
        }
70
71
        @Override
72
        public void flush() {
73
        }
74
75
        @Override
76
        public void close() throws SecurityException {
77
        }
78
    }
79
    
80
    private LH handler = new LH();
81
    
82
    private Logger logger = Logger.getLogger("test.pslogger");
83
    
84
    private PrintStreamLogger ps = (PrintStreamLogger)PrintStreamLogger.create("test.pslogger");
85
    
86
    private Object psLock;
87
88
    public PrintStreamLoggerTest(String name) {
89
        super(name);
90
    }
91
    
92
    public void setUp() throws Exception {
93
        logger.addHandler(handler);
94
        logger.setLevel(Level.INFO);
95
        logger.setUseParentHandlers(false);
96
        Field f = ps.getClass().getDeclaredField("lock");
97
        f.setAccessible(true);
98
        psLock = f.get(ps);
99
    }
100
    
101
    public void tearDown() {
102
        LogManager.getLogManager().getLogger("test.pslogger").removeHandler(handler);
103
    }
104
    
105
    public void testContinousLogingFlushes() throws Exception {
106
        int count = 0;
107
        StringBuilder data = new StringBuilder();
108
        for (int i = 0; i < 1000; i++) {
109
            data.append("12345678901234567890123456789012345678901234567890\n");
110
        }
111
        do {
112
            Thread.sleep(50);
113
            if (count < (BUFFER_THRESHOLD / data.length())) {
114
                assertEquals("Not buffering properly", 0, handler.records.size());
115
            }
116
            // 50k chars + newline
117
            ps.println(data);
118
        } while (++count < ((BUFFER_THRESHOLD / data.length()) * 2));
119
        assertFalse(handler.records.isEmpty());
120
   }
121
122
    public void testMemoryReclaimed() throws Exception {
123
        int count = 0;
124
        StringBuilder data = new StringBuilder();
125
        for (int i = 0; i < 1000; i++) {
126
            data.append("12345678901234567890123456789012345678901234567890");
127
        }
128
        
129
        do {
130
            Thread.sleep(50);
131
            if (count < (BUFFER_THRESHOLD / data.length())) {
132
                assertEquals("Not buffering properly", 0, handler.records.size());
133
            }
134
            // 50k chars + newline
135
            ps.println(data);
136
        } while (++count < ((BUFFER_THRESHOLD / data.length()) * 2));
137
        // check that the logger has started to flush already
138
        assertFalse(handler.records.isEmpty());
139
140
        // wait until flush, check that the buffer is still large.
141
        synchronized (psLock) {
142
            ps.println(data);
143
            
144
            // wait & release the lock:
145
            psLock.wait(1000);
146
147
            int[] capacity = ps.bufferSizes();
148
            assertTrue(capacity[1] >= BUFFER_THRESHOLD);
149
        }
150
        Thread.sleep(5 * BUFFER_SHRINK_TIME / 2);
151
        synchronized (psLock) {
152
            ps.println(data);
153
            
154
            // wait & release the lock:
155
            psLock.wait(1000);
156
        }
157
        int[] capacity = ps.bufferSizes();
158
        assertTrue(capacity[1] < BUFFER_THRESHOLD);
159
   }
160
}

Return to bug 269576