mono/mini/trace.c

   1 /**
   2  * \file
   3  * Tracing facilities for the Mono Runtime.
   4  *
   5  * Author:
   6  *   Paolo Molaro (lupus@ximian.com)
   7  *   Dietmar Maurer (dietmar@ximian.com)
   8  *
   9  * (C) 2002 Ximian, Inc.
  10  * Copyright 2011 Xamarin, Inc (http://www.xamarin.com)
  11  * Licensed under the MIT license. See LICENSE file in the project root for full license information.
  12  */
  13
  14 #include <config.h>
  15 #ifdef HAVE_ALLOCA_H
  16 #include <alloca.h>
  17 #endif
  18 #ifdef HAVE_UNISTD_H
  19 #include <unistd.h>
  20 #endif
  21 #include <string.h>
  22 #include "mini.h"
  23 #include "mini-runtime.h"
  24 #include <mono/metadata/debug-helpers.h>
  25 #include <mono/utils/mono-time.h>
  26 #include <mono/utils/mono-memory-model.h>
  27 #include "trace.h"
  28 #include <mono/metadata/callspec.h>
  29
  30 #if defined (HOST_ANDROID) || (defined (TARGET_IOS) && defined (TARGET_IOS))
  31 #  undef printf
  32 #  define printf(...) g_log("mono", G_LOG_LEVEL_MESSAGE, __VA_ARGS__)
  33 #  undef fprintf
  34 #  define fprintf(__ignore, ...) g_log ("mono-gc", G_LOG_LEVEL_MESSAGE, __VA_ARGS__)
  35 #endif
  36
  37 static MonoCallSpec trace_spec;
  38
  39 static volatile gint32 output_lock = 0;
  40
  41 gboolean mono_trace_eval_exception (MonoClass *klass)
  42 {
  43         return mono_callspec_eval_exception (klass, &trace_spec);
  44 }
  45
  46 gboolean mono_trace_eval (MonoMethod *method)
  47 {
  48         return mono_callspec_eval (method, &trace_spec);
  49 }
  50
  51 MonoCallSpec *mono_trace_set_options (const char *options)
  52 {
  53         char *errstr;
  54         if (!mono_callspec_parse (options, &trace_spec, &errstr)) {
  55                 fprintf (stderr, "%s\n", errstr);
  56                 g_free (errstr);
  57                 return NULL;
  58         }
  59
  60         return &trace_spec;
  61 }
  62
  63 static
  64 #ifdef MONO_KEYWORD_THREAD
  65 MONO_KEYWORD_THREAD
  66 #endif
  67 int indent_level = 0;
  68 static guint64 start_time = 0;
  69
  70 static double seconds_since_start (void)
  71 {
  72         guint64 diff = mono_100ns_ticks () - start_time;
  73         return diff/10000000.0;
  74 }
  75
  76 static void indent (int diff) {
  77         if (diff < 0)
  78                 indent_level += diff;
  79         if (start_time == 0)
  80                 start_time = mono_100ns_ticks ();
  81         printf ("[%p: %.5f %d] ", (void*)mono_native_thread_id_get (), seconds_since_start (), indent_level);
  82         if (diff > 0)
  83                 indent_level += diff;
  84 }
  85
  86 static char *
  87 string_to_utf8 (MonoString *s)
  88 {
  89         char *as;
  90         GError *gerror = NULL;
  91
  92         g_assert (s);
  93
  94         if (!s->length)
  95                 return g_strdup ("");
  96
  97         as = g_utf16_to_utf8 (mono_string_chars_internal (s), s->length, NULL, NULL, &gerror);
  98         if (gerror) {
  99                 /* Happens with StringBuilders */
 100                 g_error_free (gerror);
 101                 return g_strdup ("<INVALID UTF8>");
 102         }
 103         else
 104                 return as;
 105 }
 106
 107 /*
 108  * This used to be endianness sensitive due to the stack, but since the change
 109  * to using the profiler to get an argument, it can be dereferenced as a
 110  * pointer of the specified type, regardless of endian.
 111  */
 112 #define arg_in_stack_slot(cpos, type) ((type *)(cpos))
 113
 114 static gboolean
 115 is_gshared_vt_wrapper (MonoMethod *m)
 116 {
 117         if (m->wrapper_type != MONO_WRAPPER_OTHER)
 118                 return FALSE;
 119         return !strcmp (m->name, "interp_in") || !strcmp (m->name, "gsharedvt_out_sig");
 120 }
 121
 122 /* ENTER:i <- interp
 123  * ENTER:c <- compiled (JIT or AOT)
 124  * ENTER:u <- no JitInfo available
 125  */
 126 static char
 127 frame_kind (MonoJitInfo *ji)
 128 {
 129         if (!ji)
 130                 return 'u';
 131
 132         if (ji->is_interp)
 133                 return 'i';
 134
 135         return 'c';
 136 }
 137
 138 void
 139 mono_trace_enter_method (MonoMethod *method, MonoJitInfo *ji, MonoProfilerCallContext *ctx)
 140 {
 141         int i;
 142         MonoClass *klass;
 143         MonoObject *o;
 144         MonoMethodSignature *sig;
 145         char *fname;
 146         MonoGenericSharingContext *gsctx = NULL;
 147
 148         if (!trace_spec.enabled)
 149                 return;
 150
 151         fname = mono_method_full_name (method, TRUE);
 152         indent (1);
 153
 154         while (output_lock != 0 || mono_atomic_cas_i32 (&output_lock, 1, 0) != 0)
 155                 mono_thread_info_yield ();
 156
 157
 158         /* FIXME: Might be better to pass the ji itself */
 159         if (!ji)
 160                 ji = mini_jit_info_table_find (mono_domain_get (), (char *)MONO_RETURN_ADDRESS (), NULL);
 161
 162         printf ("ENTER:%c %s(", frame_kind (ji), fname);
 163         g_free (fname);
 164
 165         sig = mono_method_signature_internal (method);
 166
 167         if (method->is_inflated && ji) {
 168                 gsctx = mono_jit_info_get_generic_sharing_context (ji);
 169                 if (gsctx && gsctx->is_gsharedvt) {
 170                         /* Needs a ctx to get precise method */
 171                         printf (") <gsharedvt>\n");
 172                         mono_atomic_store_release (&output_lock, 0);
 173                         return;
 174                 }
 175         }
 176
 177         if (sig->hasthis) {
 178                 void *this_buf = mini_profiler_context_get_this (ctx);
 179                 if (m_class_is_valuetype (method->klass) || is_gshared_vt_wrapper (method)) {
 180                         printf ("value:%p", this_buf);
 181                 } else {
 182                         MonoObject *o = *(MonoObject**)this_buf;
 183
 184                         if (o) {
 185                                 klass = o->vtable->klass;
 186
 187                                 if (klass == mono_defaults.string_class) {
 188                                         MonoString *s = (MonoString*)o;
 189                                         char *as = string_to_utf8 (s);
 190
 191                                         printf ("this:[STRING:%p:%s]", o, as);
 192                                         g_free (as);
 193                                 } else if (klass == mono_defaults.runtimetype_class) {
 194                                         printf ("[this:[TYPE:%p:%s]]", o, mono_type_full_name (((MonoReflectionType*)o)->type));
 195                                 } else {
 196                                         printf ("this:%p[%s.%s %s]", o, m_class_get_name_space (klass), m_class_get_name (klass), o->vtable->domain->friendly_name);
 197                                 }
 198                         } else {
 199                                 printf ("this:NULL");
 200                         }
 201                 }
 202                 if (sig->param_count)
 203                         printf (", ");
 204                 mini_profiler_context_free_buffer (this_buf);
 205         }
 206
 207         for (i = 0; i < sig->param_count; ++i) {
 208                 gpointer buf = mini_profiler_context_get_argument (ctx, i);
 209
 210                 MonoType *type = sig->params [i];
 211
 212                 if (type->byref) {
 213                         printf ("[BYREF:%p]", *(gpointer*)buf);
 214                         mini_profiler_context_free_buffer (buf);
 215                         break;
 216                 }
 217
 218                 switch (mini_get_underlying_type (type)->type) {
 219                 case MONO_TYPE_I:
 220                 case MONO_TYPE_U:
 221                         printf ("%p", *arg_in_stack_slot(buf, gpointer *));
 222                         break;
 223                 case MONO_TYPE_BOOLEAN:
 224                 case MONO_TYPE_CHAR:
 225                 case MONO_TYPE_I1:
 226                 case MONO_TYPE_U1:
 227                         printf ("%d", *arg_in_stack_slot(buf, gint8));
 228                         break;
 229                 case MONO_TYPE_I2:
 230                 case MONO_TYPE_U2:
 231                         printf ("%d", *arg_in_stack_slot(buf, gint16));
 232                         break;
 233                 case MONO_TYPE_I4:
 234                 case MONO_TYPE_U4:
 235                         printf ("%d", *arg_in_stack_slot(buf, int));
 236                         break;
 237                 case MONO_TYPE_STRING: {
 238                         MonoString *s = *arg_in_stack_slot(buf, MonoString *);
 239                         if (s) {
 240                                 char *as;
 241
 242                                 g_assert (((MonoObject *)s)->vtable->klass == mono_defaults.string_class);
 243                                 as = string_to_utf8 (s);
 244
 245                                 printf ("[STRING:%p:%s]", s, as);
 246                                 g_free (as);
 247                         } else
 248                                 printf ("[STRING:null]");
 249                         break;
 250                 }
 251                 case MONO_TYPE_CLASS:
 252                 case MONO_TYPE_OBJECT: {
 253                         o = *arg_in_stack_slot(buf, MonoObject *);
 254                         if (o) {
 255                                 klass = o->vtable->klass;
 256
 257                                 gpointer data = mono_object_get_data (o);
 258                                 if (klass == mono_defaults.string_class) {
 259                                         char *as = string_to_utf8 ((MonoString*)o);
 260
 261                                         printf ("[STRING:%p:%s]", o, as);
 262                                         g_free (as);
 263                                 } else if (klass == mono_defaults.int32_class) {
 264                                         printf ("[INT32:%p:%d]", o, *(gint32 *)data);
 265                                 } else if (klass == mono_defaults.runtimetype_class) {
 266                                         printf ("[TYPE:%s]", mono_type_full_name (((MonoReflectionType*)o)->type));
 267                                 } else if (m_class_get_rank (klass)) {
 268                                         MonoArray *arr = (MonoArray*)o;
 269                                         printf ("[%s.%s:[%d]%p]", m_class_get_name_space (klass), m_class_get_name (klass), mono_array_length_internal (arr), o);
 270                                 } else
 271                                         printf ("[%s.%s:%p]", m_class_get_name_space (klass), m_class_get_name (klass), o);
 272                         } else {
 273                                 printf ("%p", *arg_in_stack_slot(buf, gpointer));
 274                         }
 275                         break;
 276                 }
 277                 case MONO_TYPE_PTR:
 278                 case MONO_TYPE_FNPTR:
 279                 case MONO_TYPE_ARRAY:
 280                 case MONO_TYPE_SZARRAY:
 281                         printf ("%p", *arg_in_stack_slot(buf, gpointer));
 282                         break;
 283                 case MONO_TYPE_I8:
 284                 case MONO_TYPE_U8:
 285                         printf ("0x%016llx", (long long)*arg_in_stack_slot(buf, gint64));
 286                         break;
 287                 case MONO_TYPE_R4:
 288                         printf ("%f", *arg_in_stack_slot(buf, float));
 289                         break;
 290                 case MONO_TYPE_R8:
 291                         printf ("%f", *arg_in_stack_slot(buf, double));
 292                         break;
 293                 case MONO_TYPE_VALUETYPE: {
 294                         int j, size, align;
 295                         size = mono_type_size (type, &align);
 296                         printf ("[");
 297                         for (j = 0; j < size; j++)
 298                                 printf ("%02x,", *((guint8*)buf +j));
 299                         printf ("]");
 300                         break;
 301                 }
 302                 default:
 303                         printf ("XX");
 304                 }
 305                 if (i + 1 < sig->param_count)
 306                         printf (", ");
 307                 mini_profiler_context_free_buffer (buf);
 308         }
 309
 310         printf (")\n");
 311         fflush (stdout);
 312
 313         mono_atomic_store_release (&output_lock, 0);
 314 }
 315
 316 void
 317 mono_trace_leave_method (MonoMethod *method, MonoJitInfo *ji, MonoProfilerCallContext *ctx)
 318 {
 319         MonoType *type;
 320         char *fname;
 321         MonoGenericSharingContext *gsctx;
 322
 323         if (!trace_spec.enabled)
 324                 return;
 325
 326         fname = mono_method_full_name (method, TRUE);
 327         indent (-1);
 328
 329         while (output_lock != 0 || mono_atomic_cas_i32 (&output_lock, 1, 0) != 0)
 330                 mono_thread_info_yield ();
 331
 332         /* FIXME: Might be better to pass the ji itself from the JIT */
 333         if (!ji)
 334                 ji = mini_jit_info_table_find (mono_domain_get (), (char *)MONO_RETURN_ADDRESS (), NULL);
 335
 336         printf ("LEAVE:%c %s(", frame_kind (ji), fname);
 337         g_free (fname);
 338
 339         if (method->is_inflated && ji) {
 340                 gsctx = mono_jit_info_get_generic_sharing_context (ji);
 341                 if (gsctx && gsctx->is_gsharedvt) {
 342                         /* Needs a ctx to get precise method */
 343                         printf (") <gsharedvt>\n");
 344                         mono_atomic_store_release (&output_lock, 0);
 345                         return;
 346                 }
 347         }
 348
 349         type = mini_get_underlying_type (mono_method_signature_internal (method)->ret);
 350
 351         gpointer buf = mini_profiler_context_get_result (ctx);
 352         switch (type->type) {
 353         case MONO_TYPE_VOID:
 354                 break;
 355         case MONO_TYPE_I1:
 356         case MONO_TYPE_U1: {
 357                 gint8 res = *arg_in_stack_slot (buf, gint8);
 358                 printf ("result=%d", res);
 359                 break;
 360         }
 361         case MONO_TYPE_I2:
 362         case MONO_TYPE_U2: {
 363                 gint16 res = *arg_in_stack_slot (buf, gint16);
 364                 printf ("result=%d", res);
 365                 break;
 366         }
 367         case MONO_TYPE_I4:
 368         case MONO_TYPE_U4: {
 369                 int res = *arg_in_stack_slot (buf, int);
 370                 printf ("result=%d", res);
 371                 break;
 372         }
 373         case MONO_TYPE_PTR:
 374         case MONO_TYPE_I:
 375         case MONO_TYPE_U: {
 376                 gpointer res = *arg_in_stack_slot (buf, gpointer);
 377                 printf ("result=%p", res);
 378                 break;
 379         }
 380         case MONO_TYPE_OBJECT: {
 381                 MonoObject *o = *arg_in_stack_slot (buf, MonoObject*);
 382
 383                 if (o) {
 384                         gpointer data = mono_object_get_data (o);
 385                         if (o->vtable->klass == mono_defaults.boolean_class) {
 386                                 printf ("[BOOLEAN:%p:%d]", o, *(guint8 *)data);
 387                         } else if  (o->vtable->klass == mono_defaults.int32_class) {
 388                                 printf ("[INT32:%p:%d]", o, *(gint32 *)data);
 389                         } else if  (o->vtable->klass == mono_defaults.int64_class) {
 390                                 printf ("[INT64:%p:%lld]", o, (long long)*(gint64 *)data);
 391                         } else if (o->vtable->klass == mono_defaults.string_class) {
 392                                 char *as;
 393                                 as = string_to_utf8 ((MonoString*)o);
 394                                 printf ("[STRING:%p:%s]", o, as);
 395                         } else {
 396                                 printf ("[%s.%s:%p]", m_class_get_name_space (mono_object_class (o)), m_class_get_name (mono_object_class (o)), o);
 397                         }
 398                 } else
 399                         printf ("[OBJECT:%p]", o);
 400
 401                 break;
 402         }
 403         case MONO_TYPE_I8: {
 404                 gint64 l =  *arg_in_stack_slot (buf, gint64);
 405                 printf ("lresult=0x%16llx", (long long)l);
 406                 break;
 407         }
 408         case MONO_TYPE_U8: {
 409                 gint64 l =  *arg_in_stack_slot (buf, gint64);
 410                 printf ("lresult=0x%16llx", (long long)l);
 411                 break;
 412         }
 413         case MONO_TYPE_R4:
 414         case MONO_TYPE_R8: {
 415                 double f = *arg_in_stack_slot (buf, double);
 416                 printf ("FP=%f", f);
 417                 break;
 418         }
 419         case MONO_TYPE_VALUETYPE:  {
 420                 guint8 *p = (guint8 *)buf;
 421                 int j, size, align;
 422                 size = mono_type_size (type, &align);
 423                 printf ("[");
 424                 for (j = 0; p && j < size; j++)
 425                         printf ("%02x,", p [j]);
 426                 printf ("]");
 427                 break;
 428         }
 429         default:
 430                 printf ("(unknown return type %x)", mono_method_signature_internal (method)->ret->type);
 431         }
 432         mini_profiler_context_free_buffer (buf);
 433
 434         //printf (" ip: %p\n", MONO_RETURN_ADDRESS_N (1));
 435         printf ("\n");
 436         fflush (stdout);
 437
 438         mono_atomic_store_release (&output_lock, 0);
 439 }
 440
 441 void
 442 mono_trace_enable (gboolean enable)
 443 {
 444         trace_spec.enabled = enable;
 445 }
 446
 447 gboolean
 448 mono_trace_is_enabled ()
 449 {
 450         return trace_spec.enabled;
 451 }