dacapolog.c 14.2 KB
Newer Older
john's avatar
john committed
1
2
3
4
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

john's avatar
john committed
5
#include <stdlib.h>
6
7
#include <sys/time.h>

8
9
#include <jni.h>

john's avatar
john committed
10
11
12
13
14
#include "dacapolog.h"
#include "dacapooptions.h"
#include "dacapotag.h"
#include "dacapolock.h"

15
16
17
18
19
#include "dacapoallocation.h"
#include "dacapoexception.h"
#include "dacapomethod.h"
#include "dacapomonitor.h"
#include "dacapothread.h"
john's avatar
john committed
20
#include "dacapocallchain.h"
21

john's avatar
john committed
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
#include "zlib.h"

MonitorLockType       lockLog;
MonitorLockType       gcLock;

#define FILE_TYPE int

#define FILE_IS_CLOSED -1
#define FILE_FLAGS      (O_WRONLY | O_CREAT | O_LARGEFILE )
#define FILE_MODE       (S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP)
#define GZ_FILE_MODE   "w"
#define GZ_BUFFER_SIZE (128*1024)

FILE_TYPE              logFile = FILE_IS_CLOSED;

gzFile                 gzLogFile;

jboolean			gzLog = FALSE;

#define CLOSE()       { \
  if (gzLog) gzclose(gzLogFile); \
  close(logFile); \
  logFile = FILE_IS_CLOSED; \
}
#define OPEN(f)        { \
  FILE_TYPE tmp = logFile; \
  gzFile    tmpgz = gzLogFile; \
  logFile = open(f,FILE_FLAGS,FILE_MODE); \
  if (gzLog) { \
    gzFile localtmpgz = gzdopen(logFile,GZ_FILE_MODE); \
    gzbuffer(localtmpgz, GZ_BUFFER_SIZE); \
    gzLogFile = localtmpgz; \
  } \
  if (tmp != FILE_IS_CLOSED) { \
    if (gzLog) gzclose(tmpgz); \
    close(tmp); \
  } \
}
    
#define FLUSH()

#define WRITE(b,e,n) { \
  if (gzLog) { logFileSequenceLength += gzwrite(gzLogFile,b,(e)*(n)); } \
  else { logFileSequenceLength += write(logFile,b,(e)*(n)); } \
}
67

john's avatar
john committed
68
jboolean			logState = FALSE;
69
jboolean            localInitDone = FALSE;
70
struct timeval      startTime;
john's avatar
john committed
71
jclass              log_java_class = NULL;
72
73
jmethodID           reportHeapID;
jfieldID            firstReportSinceForceGCID;
john's avatar
john committed
74
jfieldID            agentIntervalTimeID;
john's avatar
john committed
75

john's avatar
john committed
76
77
78
79
jfieldID            callChainCountID;
jfieldID            callChainFrequencyID;
jfieldID            callChainEnableID;

john's avatar
john committed
80
81
82
83
84
85
86
87
88
89
90
#define LOG_FILE_NAME_MAX 10000
#define LOG_FILE_EXT_MAX  10000
#define SEQUENCE_MAX        100
#define LOG_FILE_LIMIT    (1<<30)

char                baseLogFileName[LOG_FILE_NAME_MAX];
char                baseLogFileExt[LOG_FILE_EXT_MAX];
int                 fileNameSequence      = 0;
long                logFileSequenceLength = 0;
jboolean            check_limit = FALSE;

john's avatar
john committed
91
static void openLogFile() {
john's avatar
john committed
92
93
94
	char logFileName[LOG_FILE_NAME_MAX+SEQUENCE_MAX];
	int  fileSeq = fileNameSequence++;
	
john's avatar
john committed
95
96
97
98
99
100
101
102
103
104
	if (strlen(baseLogFileExt)==0) {
		if (gzLog)
			sprintf(logFileName,"%s-%d.gz",baseLogFileName,fileSeq);
		else
			sprintf(logFileName,"%s-%d",baseLogFileName,fileSeq);
	} else {
		if (gzLog)
			sprintf(logFileName,"%s-%d.%s.gz",baseLogFileName,fileSeq,baseLogFileExt);
		else
			sprintf(logFileName,"%s-%d.%s",baseLogFileName,fileSeq,baseLogFileExt);
john's avatar
john committed
105
106
	}
	
john's avatar
john committed
107
108
109
110
111
112
113
114
115
116
117
118
	OPEN(logFileName);
	
	logFileSequenceLength = 0;
}

_Bool logFileOpen() {
	return logFile != FILE_IS_CLOSED;
}

void  dacapo_log_stop() {
    if (logFile != FILE_IS_CLOSED)
    	CLOSE();
john's avatar
john committed
119
120
}

john's avatar
john committed
121
void setLogFileName(const char* log_file) {
john's avatar
john committed
122
	dacapo_log_stop();
john's avatar
john committed
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137

	int ext = strlen(log_file);
	while (0<ext && log_file[ext]!='.') ext--;

	if (0<ext) {
		strncpy(baseLogFileName,log_file,(ext<(LOG_FILE_NAME_MAX-1))?ext:(LOG_FILE_NAME_MAX-1));
		strncpy(baseLogFileExt,log_file+ext+1,SEQUENCE_MAX-1);
		baseLogFileExt[SEQUENCE_MAX-1] = '\0';
	} else {
		strcpy(baseLogFileName,log_file);
		baseLogFileExt[0]='\0';
	}

	fileNameSequence      = 0;
	logFileSequenceLength = 0;
john's avatar
john committed
138
139
	
	openLogFile(log_file);
john's avatar
john committed
140
141
}

142
void callReportHeap(JNIEnv *env) {
john's avatar
john committed
143
	(*env)->CallStaticVoidMethod(env,log_java_class,reportHeapID);
144
145
}

146
147
void setReportHeap(JNIEnv *env, jboolean flag) {
    rawMonitorEnter(&gcLock);
148
	if (localInitDone)
john's avatar
john committed
149
		(*env)->SetStaticBooleanField(env,log_java_class,firstReportSinceForceGCID,flag);
150
    rawMonitorExit(&gcLock);
151
152
}

john's avatar
john committed
153
void setReportCallChain(JNIEnv *env, jlong frequency, jboolean enable) {
154
155
	if (localInitDone) {
		if (enable) {
john's avatar
john committed
156
157
			(*env)->SetStaticLongField(env,log_java_class,callChainFrequencyID,frequency);
			(*env)->SetStaticLongField(env,log_java_class,callChainCountID,(jlong)0);
158
		}
john's avatar
john committed
159
		(*env)->SetStaticBooleanField(env,log_java_class,callChainEnableID,enable);
john's avatar
john committed
160
161
162
	}
}

john's avatar
john committed
163
_Bool dacapo_log_init() {
john's avatar
john committed
164
165
	if (!rawMonitorInit(baseEnv,"agent data",&lockLog)) {
		/* JVMTI_FUNC_PTR(baseEnv,CreateRawMonitor)(baseEnv, "agent data", &(lockLog)) != JNI_OK) */
166
167
168
		return FALSE;
	}

john's avatar
john committed
169
170
	if (!rawMonitorInit(baseEnv,"gc lock",&gcLock)) {
	    /* JVMTI_FUNC_PTR(baseEnv,CreateRawMonitor)(baseEnv, "gc lock", &(gcLock)) != JNI_OK) { */
171
172
173
174
		return FALSE;
	}
	

john's avatar
john committed
175
176
177
178
	if (isSelected(OPT_LOG_FILE_LIMIT,NULL)) {
		check_limit = TRUE;
	}

john's avatar
john committed
179
180
181
182
	if (isSelected(OPT_LOG_FILE_GZIP,NULL)) {
		gzLog = TRUE;
	}
	
john's avatar
john committed
183
	/* make log file */
184
185
	char* tmpFile = NULL;
	if (isSelected(OPT_LOG_FILE,&tmpFile)) {
john's avatar
john committed
186
		setLogFileName(tmpFile);
187
188
189
190
		if (tmpFile != NULL) {
			free(tmpFile);
			tmpFile = NULL;
		}
john's avatar
john committed
191
	}
192
193
194
	
    gettimeofday(&startTime, NULL);
    
john's avatar
john committed
195
196
197
	return TRUE;
}

198

199
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalLocalInit
200
201
202
203
  (JNIEnv *env, jclass klass)
{
	reportHeapID              = (*env)->GetStaticMethodID(env,klass,"reportHeap","()V");
	firstReportSinceForceGCID = (*env)->GetStaticFieldID(env,klass,"firstReportSinceForceGC","Z");
john's avatar
john committed
204
	agentIntervalTimeID       = (*env)->GetStaticFieldID(env,klass,"agentIntervalTime","J");
john's avatar
john committed
205
206
207
208
	callChainCountID          = (*env)->GetStaticFieldID(env,klass,"callChainCount","J");
	callChainFrequencyID      = (*env)->GetStaticFieldID(env,klass,"callChainFrequency","J");
	callChainEnableID         = (*env)->GetStaticFieldID(env,klass,"callChainEnable","Z");

john's avatar
john committed
209
	log_java_class                 = (*env)->NewGlobalRef(env, klass);
john's avatar
john committed
210
211
212
213
214
215
	
	char tmp[1024];
	if (isSelected(OPT_INTERVAL,tmp)) {
		int value = atoi(tmp);
		
		if (value > 0)
john's avatar
john committed
216
			(*env)->SetStaticLongField(env,log_java_class,agentIntervalTimeID,(jlong)value);
john's avatar
john committed
217
	}
218
219
	
	localInitDone = !FALSE;
220
221
222
223
224
225
226
227
228
229
}

JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_wierd
  (JNIEnv *env, jclass klass)
{
	fprintf(stderr,"Agent_wierd[start]\n");
	callReportHeap(env);
	fprintf(stderr,"Agent_wierd[stop]\n");
}

john's avatar
john committed
230
231
232
233
234
/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    available
 * Signature: ()Z
 */
235
JNIEXPORT jboolean JNICALL Java_org_dacapo_instrument_Agent_internalAvailable
john's avatar
john committed
236
237
238
239
240
  (JNIEnv *env, jclass klass)
{
    return !FALSE;
}

john's avatar
john committed
241
242
243
244
245
246
247
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalLogThread
  (JNIEnv *env, jclass klass, jobject thread)
{
	thread_agent_log(env, klass, thread);
}


john's avatar
john committed
248
249
250
251
252
/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    log
 * Signature: (Ljava/lang/Thread;Ljava/lang/String;Ljava/lang/String;)V
 */
253
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalLog
john's avatar
john committed
254
255
256
  (JNIEnv *env, jclass klass, jobject thread, jstring e, jstring m)
{
    if (logState) {
john's avatar
john committed
257
258
		jniNativeInterface* jni_table = JNIFunctionTable();

john's avatar
john committed
259
260
261
	    jboolean iscopy_e;
	    jboolean iscopy_m;
	    jlong    thread_tag = 0;
john's avatar
john committed
262
263
	    jlong    thread_klass_tag = 0;
	    jclass   thread_klass = JVM_FUNC_PTR(jni_table,GetObjectClass)(env,thread);
264
	    jboolean new_thread_tag;
john's avatar
john committed
265

266
		rawMonitorEnter(&lockTag);
267
		jboolean thread_has_new_tag = getTag(thread, &thread_tag);
john's avatar
john committed
268
		jboolean thread_klass_has_new_tag = getTag(thread_klass, &thread_klass_tag);
269
		rawMonitorExit(&lockTag);
john's avatar
john committed
270
271
272
273

	    const char *c_e = JVMTI_FUNC_PTR(env,GetStringUTFChars)(env, e, &iscopy_e);
	    const char *c_m = JVMTI_FUNC_PTR(env,GetStringUTFChars)(env, m, &iscopy_m);

274
	    rawMonitorEnter(&lockLog);
john's avatar
john committed
275
	    log_field_string(c_e);
276
		log_field_current_time();
john's avatar
john committed
277
278
		
		log_thread(thread, thread_tag, thread_has_new_tag, thread_klass, thread_klass_tag, thread_klass_has_new_tag);
279
		
john's avatar
john committed
280
281
	    log_field_string(c_m);
	    log_eol();
282
	    rawMonitorExit(&lockLog);
john's avatar
john committed
283
284
285
286
287
288
289
290
291
292
293

	    JVMTI_FUNC_PTR(env,ReleaseStringUTFChars)(env, e, c_e);
	    JVMTI_FUNC_PTR(env,ReleaseStringUTFChars)(env, m, c_m);
    }
}

/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    setLogFileName
 * Signature: (Ljava/lang/String;)V
 */
294
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalSetLogFileName
john's avatar
john committed
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
  (JNIEnv *env, jclass klass, jstring s)
{
    jboolean iscopy;
    const char *m = JVMTI_FUNC_PTR(env,GetStringUTFChars)(env, s, &iscopy);

    setLogFileName(m);

    JVMTI_FUNC_PTR(env,ReleaseStringUTFChars)(env, s, m);
}

/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    start
 * Signature: ()V
 */
john's avatar
john committed
310
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalStart
john's avatar
john committed
311
312
  (JNIEnv *env, jclass klass)
{
john's avatar
john committed
313
    if (!logState) {
john's avatar
john committed
314
	    logState = logFile != FILE_IS_CLOSED;
john's avatar
john committed
315
	    if (logState) {
316
		    rawMonitorEnter(&lockLog);
317
	    	log_field_string(LOG_PREFIX_START);
318
	    	log_field_current_time();
john's avatar
john committed
319
	    	log_eol();
320
		    rawMonitorExit(&lockLog);
321
322
323
324
325
326
	    	
	    	allocation_logon(env);
			exception_logon(env);
			method_logon(env);
			monitor_logon(env);
			thread_logon(env);
john's avatar
john committed
327
			call_chain_logon(env);
john's avatar
john committed
328
	    }
john's avatar
john committed
329
330
331
332
333
334
335
336
	}
}

/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    stop
 * Signature: ()V
 */
john's avatar
john committed
337
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalStop
john's avatar
john committed
338
339
340
341
342
  (JNIEnv *env, jclass klass)
{
	jboolean tmp = logState;
    logState = FALSE;
    if (tmp) {
john's avatar
john committed
343
	    rawMonitorEnter(&lockLog);
344
    	log_field_string(LOG_PREFIX_STOP);
345
    	log_field_current_time();
john's avatar
john committed
346
    	log_eol();
john's avatar
john committed
347
	    rawMonitorExit(&lockLog);
john's avatar
john committed
348
349
350
351
352
	}
}



john's avatar
john committed
353
354
355
356
357
/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    logCallChain
 * Signature: (Ljava/lang/Thread;)V
 */
358
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalLogCallChain
john's avatar
john committed
359
360
361
362
  (JNIEnv *env, jclass klass, jobject thread) {
  	log_call_chain(env, klass, thread);
}

363
364
365
366
367
/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    writeHeapReport
 * Signature: (JJJJ)V
 */
368
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_internalHeapReport(JNIEnv *local_env, jclass klass, jobject thread, jlong used, jlong free, jlong total, jlong max) {
john's avatar
john committed
369
370
	jniNativeInterface* jni_table = JNIFunctionTable();

371
	jlong thread_tag = 0;
john's avatar
john committed
372
373
	jclass thread_klass = JVM_FUNC_PTR(jni_table,GetObjectClass)(local_env,thread);
	jlong thread_klass_tag = 0;
374

375
	rawMonitorEnter(&lockTag);
376
	jboolean thread_has_new_tag = getTag(thread, &thread_tag);
john's avatar
john committed
377
	jboolean thread_klass_has_new_tag = getTag(thread_klass, &thread_klass_tag);
378
	rawMonitorExit(&lockTag);
379

380
	rawMonitorEnter(&lockLog);
381
	log_field_string(LOG_PREFIX_HEAP_REPORT);
382
	log_field_current_time();
383

john's avatar
john committed
384
	log_thread(thread, thread_tag, thread_has_new_tag, thread_klass, thread_klass_tag, thread_klass_has_new_tag);
385
386
387
388
389
390
	
	log_field_jlong(used);
	log_field_jlong(free);
	log_field_jlong(total);
	log_field_jlong(max);
	log_eol();    
391
	rawMonitorExit(&lockLog);
392
393
394
395
	
    return;
}

john's avatar
john committed
396
397
398
399
400
401
402
403
404
405
406
/*
 */

static _Bool first_field     = TRUE;
static char  field_separator = ',';
static char  field_delimiter = '\"';
static char  end_of_line     = '\n';

/* */

static void write_field(const char* text, int text_length, _Bool use_delimiter) {
john's avatar
john committed
407
408
409
410
411
412
  if (logFile == FILE_IS_CLOSED) {
  	fprintf(stderr,"LOG_FILE IS CLOSED\n");
  	exit(10);
  }

  if (first_field) {
john's avatar
john committed
413
    first_field = FALSE;
john's avatar
john committed
414
415
416
  } else {
    WRITE(&field_separator,sizeof(char),1);
  }
john's avatar
john committed
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
  
  if (use_delimiter) {
    char temp_field[10240];
    int  temp_length = 0;

    temp_field[temp_length++] = field_delimiter;
  
	if (text!=NULL) {
	  int i;
	  for(i=0; i<text_length;++i) {
	    if (text[i]==field_delimiter)
	      temp_field[temp_length++] = field_delimiter;
        temp_field[temp_length++] = field_delimiter;
	  }
	}
    
    temp_field[temp_length++] = field_delimiter;

john's avatar
john committed
435
    WRITE(temp_field,sizeof(char),temp_length);
john's avatar
john committed
436
  } else {
john's avatar
john committed
437
    if(text!=NULL && 0<text_length) {
john's avatar
john committed
438
      WRITE(text,sizeof(char),text_length);
john's avatar
john committed
439
    }
john's avatar
john committed
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
  }
}

void log_field_string(const char* text) {
  if (text==NULL)
    write_field(NULL,0,TRUE);
  else {
    int text_length = 0;
    _Bool use_delimiter = FALSE;
    
    while(text[text_length]!='\0') {
       use_delimiter = text[text_length]==field_delimiter || text[text_length]==field_separator;
       ++text_length;
    }
    
    write_field(text,text_length,use_delimiter);
  }
}

void log_field_jboolean(jboolean v) {
  log_field_string(v?"true":"false");
}

void log_field_int(int v) {
  char tmp[32];
  sprintf(tmp,"%d",v);
  log_field_string(tmp);
}

void log_field_jlong(jlong v) {
  char tmp[64];
  sprintf(tmp,"%" FORMAT_JLONG,v);
  log_field_string(tmp);
}

475
476
477
478
479
480
void log_field_long(long v) {
  char tmp[64];
  sprintf(tmp,"%ld",v);
  log_field_string(tmp);
}

john's avatar
john committed
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
void log_field_pointer(const void* p) {
  char tmp[64];
  sprintf(tmp,"%" FORMAT_PTR, PTR_CAST(p));
  log_field_string(tmp);
}

void log_field_string_n(const char* text, int field_length) {
  int i;
  _Bool use_delimiter = FALSE;
  
  for(i=0; i<field_length && !use_delimiter; ++i) {
  	use_delimiter = text[i]==field_delimiter || text[i]==field_separator;
  }
  
  write_field(text,field_length,use_delimiter);
}

john's avatar
john committed
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
void log_thread(jthread thread, jlong thread_tag, jboolean thread_has_new_tag, jobject klass, jlong klass_tag, jboolean klass_has_new_tag) {
	log_field_jlong(thread_tag);

	if (thread_has_new_tag) {
		jniNativeInterface* jni_table = JNIFunctionTable();

		// get thread name.
		jvmtiThreadInfo info;
		JVMTI_FUNC_PTR(baseEnv,GetThreadInfo)(baseEnv, thread, &info);
		log_field_string(info.name);
		if (info.name!=NULL) JVMTI_FUNC_PTR(baseEnv,Deallocate)(baseEnv,(unsigned char*)info.name);
	} else {
		log_field_string(NULL);
	}
	
	log_class(klass, klass_tag, klass_has_new_tag);
}

void log_class(jobject klass, jlong klass_tag, jboolean klass_has_new_tag) {
	log_field_jlong(klass_tag);
	if (klass_has_new_tag) {
		jniNativeInterface* jni_table = JNIFunctionTable();

		char* signature = NULL;
		char* generic = NULL;
		
		JVMTI_FUNC_PTR(baseEnv,GetClassSignature)(baseEnv,klass,&signature,&generic);
		log_field_string(signature);
		
		if (signature!=NULL) JVMTI_FUNC_PTR(baseEnv,Deallocate)(baseEnv,(unsigned char*)signature);
		if (generic!=NULL) JVMTI_FUNC_PTR(baseEnv,Deallocate)(baseEnv,(unsigned char*)generic);
	} else {
		log_field_string(NULL);
	}
}

534
void log_field_time(struct timeval* tv) {
john's avatar
john committed
535
536
    jlong t = ((jlong)(tv->tv_sec - startTime.tv_sec)) * (jlong)1000000 + (tv->tv_usec - startTime.tv_usec);
    log_field_jlong(t);
537
538
539
}

void log_field_current_time() {
540
541
	struct timeval tv;
    gettimeofday(&tv, NULL);
542
    log_field_time(&tv);
543
544
}

john's avatar
john committed
545
void log_eol() {
john's avatar
john committed
546
  WRITE(&end_of_line,sizeof(char),1);
john's avatar
john committed
547
  first_field = TRUE;
john's avatar
john committed
548
  FLUSH();
john's avatar
john committed
549
550
551
552
  
  if (check_limit && LOG_FILE_LIMIT <= logFileSequenceLength) {
  	openLogFile();
  }  
john's avatar
john committed
553
}
john's avatar
john committed
554

555
556
557
558
559
/*
 * Class:     org_dacapo_instrument_Agent
 * Method:    agentThread
 * Signature: (Ljava/lang/Thread;)V
 */
john's avatar
john committed
560
JNIEXPORT void JNICALL Java_org_dacapo_instrument_Agent_agentThread(JNIEnv *env, jclass klass, jobject thread) {
561
	threads_states(env);
562
563
}

john's avatar
john committed
564