1 /*
2 * Copyright (c) 2014, 2015, Dynatrace and/or its affiliates. All rights reserved.
3 *
4 * This file is part of the Lock Contention Tracing Subsystem for the HotSpot
5 * Virtual Machine, which is developed at Christian Doppler Laboratory on
6 * Monitoring and Evolution of Very-Large-Scale Software Systems. Please
7 * contact us at <http://mevss.jku.at/> if you need additional information
8 * or have any questions.
9 *
10 * This code is free software; you can redistribute it and/or modify it
11 * under the terms of the GNU General Public License version 2 only, as
12 * published by the Free Software Foundation.
13 *
14 * This code is distributed in the hope that it will be useful, but WITHOUT
15 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
16 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
17 * version 2 for more details (a copy is included in the LICENSE file that
18 * accompanied this code).
19 *
20 * You should have received a copy of the GNU General Public License version
21 * 2 along with this work. If not, see <http://www.gnu.org/licenses/>.
22 *
23 */
24
25 #include "evtrace/traceManager.hpp"
26
27 #include "evtrace/traceBuffer.hpp"
28 #include "evtrace/traceBufferQueue.hpp"
29 #include "evtrace/traceReaderThread.hpp"
30 #include "evtrace/traceEvents.hpp"
31
32 #include "runtime/javaCalls.hpp"
33 #include "runtime/thread.hpp"
34
35 volatile bool TraceManager::_is_initialized = false;
36 TraceReaderThread *TraceManager::_thread = NULL;
37 Monitor *TraceManager::_thread_mtx = NULL;
38 volatile bool TraceManager::_thread_running = false;
39 TraceBufferQueue *TraceManager::_flush_queue = NULL;
40 TraceBufferQueue *TraceManager::_free_queue = NULL;
41 TraceMetadata *TraceManager::_metadata = NULL;
42 bool TraceManager::_classes_unloaded_in_current_safepoint = false;
43 DEBUG_ONLY(int TraceManager::_current_safepoint_counter);
44
45 // statistics
46 volatile intptr_t TraceManager::_buffer_count = 0xdead;
47 volatile intptr_t TraceManager::_max_buffer_count = 0xdead;
48 volatile intptr_t TraceManager::_allocated_buffer_count = 0xdead;
49 volatile intptr_t TraceManager::_submitted_trace_bytes = 0xdead;
50 intptr_t TraceManager::_reclaimed_trace_bytes = 0xdead;
51 volatile intptr_t TraceManager::_reclaim_time_nanos = 0xdead;
52 intptr_t TraceManager::_stored_free_enqueue_ops = 0xdead;
53 intptr_t TraceManager::_stored_free_dequeue_ops = 0xdead;
54 intptr_t TraceManager::_stored_flush_enqueue_ops = 0xdead;
55 intptr_t TraceManager::_stored_flush_dequeue_ops = 0xdead;
56 volatile intptr_t TraceManager::_total_stack_traces = 0xdead;
57 volatile intptr_t TraceManager::_truncated_stack_traces = 0xdead;
58 volatile intptr_t TraceManager::_reused_memento_stack_traces = 0xdead;
59 volatile intptr_t TraceManager::_total_stack_frames = 0xdead;
60 volatile intptr_t TraceManager::_reused_memento_stack_frames = 0xdead;
61
62 void TraceManager::initialize() {
63 assert(!_is_initialized, "already initialized");
64 assert(_flush_queue == NULL, "flush queue exists");
65 assert(_free_queue == NULL, "free queue exists");
66 assert(_thread == NULL, "thread exists");
67 assert(!_thread_running, "thread running");
68 assert(_metadata == NULL, "metadata exists");
69 assert(!_classes_unloaded_in_current_safepoint, "must be unset");
70
71 // nothing should be allocated before this point
72 // NOTE: requires -XX:NativeMemoryTracking=summary or =detail
73 assert(MallocMemorySummary::as_snapshot()->by_type(mtEventTracing)->malloc_size() == 0, "premature event tracing allocations");
74
75 guarantee(EventTracingStackDepthLimit <= TRACE_STACK_MAX_FRAMES, "stack depth limit is too high");
76 if (EventTracingStackDepthLimit == 0) {
77 EnableEventTracingStackTraces = false;
78 }
79
80 TraceEvents::initialize();
81
82 _metadata = new TraceMetadata();
83
84 _thread_mtx = new Monitor(Mutex::nonleaf + 1, "TraceManager::_thread_mtx");
85
86 _buffer_count = 0;
87 _flush_queue = new TraceBufferQueue();
88
89 if (EnableEventTracingBufferReuse) {
90 _free_queue = new TraceBufferQueue();
91
92 for (uintx i = 0; i < EventTracingPreallocatedBuffers; i++) {
93 _free_queue->enqueue(allocate_buffer());
94 }
95 assert((jlong)_free_queue->count() == (jlong) EventTracingPreallocatedBuffers, "sanity");
96 }
97
98 _is_initialized = true;
99
100 reset_stats();
101 }
102
103 Handle TraceManager::create_queue_object(TraceBufferQueue *q, instanceKlassHandle klass, TRAPS) {
104 JavaValue result(T_OBJECT);
105 result.set_jobject(NULL);
106 if (q != NULL) {
107 JavaCallArguments args;
108 args.push_long((jlong) q);
109 JavaCalls::call_static(&result,
110 klass,
111 vmSymbols::TraceBufferQueue_from_handle_method_name(),
112 vmSymbols::TraceBufferQueue_from_handle_method_signature(),
113 &args,
114 CHECK_NH);
115 }
116 return Handle(THREAD, (oop) result.get_jobject());
117 }
118
119 void TraceManager::start_threads(TRAPS) {
120 assert(_thread == NULL && !_thread_running, "trace reader thread exists");
121
122 Klass* qk = SystemDictionary::resolve_or_fail(vmSymbols::sun_evtracing_TraceBufferQueue(), true, CHECK);
123 instanceKlassHandle q_klass(THREAD, qk);
124 q_klass->initialize(CHECK);
125
126 Handle flushq = create_queue_object(_flush_queue, q_klass, CHECK);
127 Handle freeq = create_queue_object(_free_queue, q_klass, CHECK);
128
129 _thread = TraceReaderThread::start(flushq(), freeq(), THREAD);
130 _thread_running = true;
131 }
132
133 class TraceManager::ReclaimTraceBuffersClosure : public ThreadClosure {
134 bool _deinitialize;
135 jlong _reclaimed_bytes;
136
137 public:
138 ReclaimTraceBuffersClosure(bool deinit)
139 : _deinitialize(deinit), _reclaimed_bytes(0)
140 {
141 }
142
143 ~ReclaimTraceBuffersClosure() { }
144
145 virtual void do_thread(Thread *t) {
146 assert(t != NULL, "null thread");
147
148 TraceBuffer *buffer = t->trace_buffer();
149 if (buffer != NULL && (_deinitialize || buffer->filled_size() > 0)) {
150 TraceManager::pre_submit_buffer(buffer);
151 _reclaimed_bytes += buffer->filled_size();
152 TraceManager::_flush_queue->enqueue(buffer);
153
154 buffer = NULL;
155 if (!_deinitialize && EnableEventTracingBufferReuse) {
156 buffer = TraceManager::_free_queue->try_dequeue();
157 if (buffer != NULL) {
158 buffer->owner = t;
159 }
160 }
161 t->set_trace_buffer(buffer);
162 }
163 }
164
165 jlong reclaimed_bytes() { return _reclaimed_bytes; }
166 };
167
168 class TraceManager::VM_ReclaimTraceBuffers : public VM_Operation {
169 bool _deinitialize;
170 jlong _queue_fill_mark;
171
172 public:
173 VM_ReclaimTraceBuffers(bool deinit) : _deinitialize(deinit) {}
174 VMOp_Type type() const { return VMOp_ReclaimTraceBuffers; }
175 void doit();
176
177 jlong queue_fill_mark() { return _queue_fill_mark; }
178 };
179
180 void TraceManager::VM_ReclaimTraceBuffers::doit() {
181 assert(SafepointSynchronize::is_at_safepoint() && Thread::current()->is_VM_thread(), "sanity");
182
183 if (_deinitialize) {
184 TraceEvents::write_vm_end();
185
186 // stop threads from acquiring buffers
187 TraceManager::_is_initialized = false;
188 }
189
190 TraceManager::ReclaimTraceBuffersClosure cl(_deinitialize);
191 Threads::threads_do(&cl);
192
193 _queue_fill_mark = TraceManager::_flush_queue->fill_mark();
194 TraceManager::_reclaimed_trace_bytes += cl.reclaimed_bytes();
195
196 if (_thread != NULL && _thread->is_polling_queue()) {
197 // reader thread is sleeping in poll loop, interrupt
198
199 // we don't want to interrupt the thread elsewhere, for example during
200 // NIO channel operations, when an interrupt shuts down the channel
201 Thread::interrupt(_thread);
202 }
203 }
204
205 void TraceManager::reclaim_buffers_in_safepoint(bool wait_until_processed) {
206 assert_initialized();
207
208 jlong reclaim_start = os::javaTimeNanos();
209
210 jlong fill_mark = do_reclaim_buffers_in_safepoint(false);
211
212 if (wait_until_processed) {
213 // NOTE: this doesn't actually wait until the last buffer has been
214 // *processed*, only until the reader thread has *dequeued*
215 // the last reclaimed buffer (usually when the second-to-last
216 // buffer has been processed)
217 while (!_flush_queue->has_dequeued_at_mark(fill_mark)) {
218 os::sleep(Thread::current(), 1, true);
219 }
220 }
221
222 if (EnableEventTracingDiagnostics) {
223 // FIXME: counter value depends on whether callers set wait_until_processed
224 jlong duration = os::javaTimeNanos() - reclaim_start;
225 Atomic::add_ptr(duration, &_reclaim_time_nanos);
226 }
227 }
228
229 jlong TraceManager::do_reclaim_buffers_in_safepoint(bool deinit) {
230 VM_ReclaimTraceBuffers op(deinit);
231 VMThread::execute(&op);
232
233 return op.queue_fill_mark();
234 }
235
236 class TraceManager::VM_ResetTraceMetadata : public VM_Operation {
237 public:
238 VM_ResetTraceMetadata() {}
239 VMOp_Type type() const { return VMOp_ResetTraceMetadata; }
240 void doit();
241 bool allow_nested_vm_operations() const { return true; }
242 };
243
244 void TraceManager::VM_ResetTraceMetadata::doit() {
245 assert(SafepointSynchronize::is_at_safepoint() && Thread::current()->is_VM_thread(), "sanity");
246
247 VM_ReclaimTraceBuffers reclaim_op(false);
248 VMThread::execute(&reclaim_op);
249
250 if (_thread != NULL && _thread->is_polling_queue() && _thread->trace_buffer() != NULL) {
251 // The ReclaimTraceBuffers VM op has interrupted the reader thread, which
252 // generated a ThreadInterrupt event containing a sequence number.
253 // Therefore, this event must be submitted before the metadata reset event.
254
255 submit_buffer(Thread::current()->trace_buffer());
256 Thread::current()->set_trace_buffer(NULL);
257 }
258
259 TraceManager::_metadata->purge_all();
260
261 TraceEvents::write_metadata_reset();
262 if (Thread::current()->trace_buffer() != NULL) {
263 submit_buffer(Thread::current()->trace_buffer());
264 Thread::current()->set_trace_buffer(NULL);
265 }
266 }
267
268 void TraceManager::reset_metadata() {
269 VM_ResetTraceMetadata op;
270 VMThread::execute(&op);
271 }
272
273 void TraceManager::nmethod_is_unloading(const nmethod *nm) {
274 if (_is_initialized) {
275 _metadata->purge_unloading_nmethod(nm);
276 }
277 }
278
279 void TraceManager::class_loader_is_unloading(ClassLoaderData *loader) {
280 assert(SafepointSynchronize::is_at_safepoint() && Thread::current()->is_VM_thread(), "sanity");
281
282 if (!_is_initialized)
283 return;
284
285 // When classes and methods are unloaded during garbage collection, their
286 // memory is reclaimed and other classes and methods can be loaded in their
287 // place. Since we use addresses as unique identifiers, we need to observe
288 // such unload events and purge any references to unloaded metadata from
289 // our records.
290 //
291 // Trace analysis must also be aware of unloads as well since any trace
292 // events after an unload can use the same identifiers to refer to different
293 // data. Therefore, we reclaim the trace buffers from all threads at this
294 // point. We then write one or multiple unload events to the trace buffer of
295 // the VM thread, and finally enqueue that buffer before the end of the
296 // safepoint. Therefore, when processing the buffers in the order in which
297 // they are enqueued, trace analysis encounters the necessary unload events
298 // before any events after the unload.
299
300 if (!_classes_unloaded_in_current_safepoint) {
301 // G1 doesn't allow nested VM ops
302 VM_ReclaimTraceBuffers(false).doit();
303 _classes_unloaded_in_current_safepoint = true;
304 DEBUG_ONLY(_current_safepoint_counter = SafepointSynchronize::_safepoint_counter);
305 } else {
306 assert(_current_safepoint_counter == SafepointSynchronize::_safepoint_counter, "different safepoint");
307 }
308
309 TraceEvents::write_class_loader_unload(loader);
310
311 _metadata->purge_unloading_classes(loader);
312 }
313
314 void TraceManager::do_work_before_safepoint_end() {
315 assert(SafepointSynchronize::is_at_safepoint() && Thread::current()->is_VM_thread(), "sanity");
316
317 if (_is_initialized) {
318 VM_ReclaimTraceBuffers(false).doit(); // don't bother with VM op
319
320 if (_classes_unloaded_in_current_safepoint) {
321 assert(_current_safepoint_counter == SafepointSynchronize::_safepoint_counter, "different safepoint");
322 _classes_unloaded_in_current_safepoint = false;
323 }
324
325 _metadata->do_maintenance();
326 }
327 }
328
329 void TraceManager::thread_is_exiting(TraceReaderThread* t) {
330 guarantee(!_is_initialized, "thread exiting prematurely");
331 guarantee(t == _thread, "unexpected thread");
332 guarantee(_thread_running, "not running?");
333
334 MonitorLockerEx ml(_thread_mtx);
335 _thread_running = false;
336 ml.notify_all();
337 }
338
339 void TraceManager::finish_and_destroy(TRAPS) {
340 assert_initialized();
341 assert(_thread != NULL, "thread not initialized");
342
343 jlong reclaim_start = os::javaTimeNanos();
344
345 // This just sets a flag that the reader thread only checks once queue
346 // operations fail after the reclaim op
347 _thread->shutdown(CHECK);
348
349 _thread_mtx->lock();
350
351 do_reclaim_buffers_in_safepoint(true);
352
353 while(_thread_running) {
354 _thread_mtx->wait(); // wait for trace reader thread to call back
355 }
356 _thread_mtx->unlock();
357 delete _thread_mtx;
358 _thread_mtx = NULL;
359 _thread = NULL; // NOTE: thread deletes itself on exit
360
361 if (EnableEventTracingDiagnostics) {
362 _reclaim_time_nanos += (os::javaTimeNanos() - reclaim_start);
363 }
364
365 // We keep these around to provide statistics to agents after deinitialization (during shutdown)
366 // FIXME: we should fill a single TraceStatistics object instead of all those variables
367 if (EnableEventTracingBufferReuse) {
368 _stored_free_enqueue_ops = _free_queue->enqueue_ops() - _stored_free_enqueue_ops;
369 _stored_free_dequeue_ops = _free_queue->dequeue_ops() - _stored_free_dequeue_ops;
370 }
371 _stored_flush_enqueue_ops = _flush_queue->enqueue_ops() - _stored_flush_enqueue_ops;
372 _stored_flush_dequeue_ops = _flush_queue->dequeue_ops() - _stored_flush_dequeue_ops;
373
374 assert(_flush_queue->is_empty(), "flush queue not empty");
375 delete _flush_queue;
376 _flush_queue = NULL;
377
378 if (EnableEventTracingBufferReuse) {
379 while (!_free_queue->is_empty()) {
380 TraceBuffer *buffer = _free_queue->try_dequeue();
381 assert(buffer != NULL, "null buffer from non-empty queue");
382 free_buffer(buffer);
383 }
384 delete _free_queue;
385 _free_queue = NULL;
386 }
387 assert(_free_queue == NULL, "sanity");
388
389 delete _metadata;
390 _metadata = NULL;
391
392 // all event tracing memory must be deallocated here
393 // NOTE: requires -XX:NativeMemoryTracking=summary or =detail
394 assert(MallocMemorySummary::as_snapshot()->by_type(mtEventTracing)->malloc_size() == 0, "memory leak");
395 }
396
397 void TraceManager::write_stats(TraceStatistics *stats) {
398 assert(!_is_initialized || _flush_queue != NULL, "sanity");
399
400 if (EnableEventTracingBufferReuse) {
401 jlong free_enqueue_ops, free_dequeue_ops;
402 free_enqueue_ops = _is_initialized ? _free_queue->enqueue_ops() - _stored_free_enqueue_ops : _stored_free_enqueue_ops;
403 free_dequeue_ops = _is_initialized ? _free_queue->dequeue_ops() - _stored_free_dequeue_ops : _stored_free_dequeue_ops;
404 stats->add_entry("free_enqueue_ops", free_enqueue_ops);
405 stats->add_entry("free_dequeue_ops", free_dequeue_ops);
406 }
407
408 jlong flush_enqueue_ops, flush_dequeue_ops;
409 flush_enqueue_ops = _is_initialized ? _flush_queue->enqueue_ops() - _stored_flush_enqueue_ops : _stored_flush_enqueue_ops;
410 flush_dequeue_ops = _is_initialized ? _flush_queue->dequeue_ops() - _stored_flush_dequeue_ops : _stored_flush_dequeue_ops;
411 stats->add_entry("flush_enqueue_ops", flush_enqueue_ops);
412 stats->add_entry("flush_dequeue_ops", flush_dequeue_ops);
413
414 stats->add_entry("mean_buffer_capacity", EventTracingBufferCapacity);
415 stats->add_entry("reclaimed_trace_bytes", _reclaimed_trace_bytes);
416
417 if (EnableEventTracingDiagnostics) {
418 stats->add_entry("submitted_trace_bytes", _submitted_trace_bytes);
419 stats->add_entry("reclaim_time_nanos", _reclaim_time_nanos);
420 stats->add_entry("stack_cache_lookups", _metadata->stack_cache_lookups());
421 stats->add_entry("stack_cache_lookup_misses", _metadata->stack_cache_lookup_misses());
422 stats->add_entry("stack_cache_lookup_collisions", _metadata->stack_cache_lookup_collisions());
423 stats->add_entry("stack_cache_probes", _metadata->stack_cache_probes());
424 stats->add_entry("stack_cache_probe_collisions", _metadata->stack_cache_probe_collisions());
425 stats->add_entry("stack_cache_purge_millis", _metadata->stack_cache_purge_millis());
426 stats->add_entry("stack_cache_maintenance_millis", _metadata->stack_cache_maintenance_millis());
427 stats->add_entry("total_stack_traces", _total_stack_traces);
428 stats->add_entry("truncated_stack_traces", _truncated_stack_traces);
429 stats->add_entry("reused_memento_stack_traces", _reused_memento_stack_traces);
430 stats->add_entry("total_stack_frames", _total_stack_frames);
431 stats->add_entry("reused_memento_stack_frames", _reused_memento_stack_frames);
432 stats->add_entry("buffer_count", _buffer_count);
433 stats->add_entry("max_buffer_count", _max_buffer_count);
434 stats->add_entry("allocated_buffer_count", _allocated_buffer_count);
435 }
436 }
437
438 void TraceManager::reset_stats() {
439 assert(!_is_initialized || _flush_queue != NULL, "sanity");
440
441 if (_is_initialized) {
442 if (EnableEventTracingBufferReuse) {
443 _stored_free_enqueue_ops = _free_queue->enqueue_ops();
444 _stored_free_dequeue_ops = _free_queue->dequeue_ops();
445 }
446
447 _stored_flush_enqueue_ops = _flush_queue->enqueue_ops();
448 _stored_flush_dequeue_ops = _flush_queue->dequeue_ops();
449 }
450
451 _reclaimed_trace_bytes = 0;
452
453 if (EnableEventTracingDiagnostics) {
454 _submitted_trace_bytes = 0;
455 _reclaim_time_nanos = 0;
456 _total_stack_traces = 0;
457 _truncated_stack_traces = 0;
458 _reused_memento_stack_traces = 0;
459 _total_stack_frames = 0;
460 _reused_memento_stack_frames = 0;
461 _max_buffer_count = _buffer_count;
462 _allocated_buffer_count = 0;
463
464 _metadata->reset_stack_cache_stats();
465 }
466 }