1 /*
2  * Copyright 2016 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 #include "jit_logger.h"
18 
19 #include "arch/instruction_set.h"
20 #include "art_method-inl.h"
21 #include "base/time_utils.h"
22 #include "base/unix_file/fd_file.h"
23 #include "driver/compiler_driver.h"
24 #include "jit/jit.h"
25 #include "jit/jit_code_cache.h"
26 #include "oat_file-inl.h"
27 
28 namespace art {
29 namespace jit {
30 
31 #ifdef ART_TARGET_ANDROID
32 static const char* kLogPrefix = "/data/misc/trace";
33 #else
34 static const char* kLogPrefix = "/tmp";
35 #endif
36 
37 // File format of perf-PID.map:
38 // +---------------------+
39 // |ADDR SIZE symbolname1|
40 // |ADDR SIZE symbolname2|
41 // |...                  |
42 // +---------------------+
OpenPerfMapLog()43 void JitLogger::OpenPerfMapLog() {
44   std::string pid_str = std::to_string(getpid());
45   std::string perf_filename = std::string(kLogPrefix) + "/perf-" + pid_str + ".map";
46   perf_file_.reset(OS::CreateEmptyFileWriteOnly(perf_filename.c_str()));
47   if (perf_file_ == nullptr) {
48     LOG(ERROR) << "Could not create perf file at " << perf_filename <<
49       " Are you on a user build? Perf only works on userdebug/eng builds";
50   }
51 }
52 
WritePerfMapLog(JitCodeCache * code_cache,ArtMethod * method,bool osr)53 void JitLogger::WritePerfMapLog(JitCodeCache* code_cache, ArtMethod* method, bool osr) {
54   if (perf_file_ != nullptr) {
55     const void* ptr = osr ? code_cache->LookupOsrMethodHeader(method)->GetCode()
56                           : method->GetEntryPointFromQuickCompiledCode();
57     size_t code_size = code_cache->GetMemorySizeOfCodePointer(ptr);
58     std::string method_name = method->PrettyMethod();
59 
60     std::ostringstream stream;
61     stream << std::hex
62            << reinterpret_cast<uintptr_t>(ptr)
63            << " "
64            << code_size
65            << " "
66            << method_name
67            << std::endl;
68     std::string str = stream.str();
69     bool res = perf_file_->WriteFully(str.c_str(), str.size());
70     if (!res) {
71       LOG(WARNING) << "Failed to write jitted method info in log: write failure.";
72     }
73   } else {
74     LOG(WARNING) << "Failed to write jitted method info in log: log file doesn't exist.";
75   }
76 }
77 
ClosePerfMapLog()78 void JitLogger::ClosePerfMapLog() {
79   if (perf_file_ != nullptr) {
80     UNUSED(perf_file_->Flush());
81     UNUSED(perf_file_->Close());
82   }
83 }
84 
85 //  File format of jit-PID.jump:
86 //
87 //  +--------------------------------+
88 //  |  PerfJitHeader                 |
89 //  +--------------------------------+
90 //  |  PerfJitCodeLoad {             | .
91 //  |    struct PerfJitBase;         |  .
92 //  |    uint32_t process_id_;       |   .
93 //  |    uint32_t thread_id_;        |   .
94 //  |    uint64_t vma_;              |   .
95 //  |    uint64_t code_address_;     |   .
96 //  |    uint64_t code_size_;        |   .
97 //  |    uint64_t code_id_;          |   .
98 //  |  }                             |   .
99 //  +-                              -+   .
100 //  |  method_name'\0'               |   +--> one jitted method
101 //  +-                              -+   .
102 //  |  jitted code binary            |   .
103 //  |  ...                           |   .
104 //  +--------------------------------+   .
105 //  |  PerfJitCodeDebugInfo     {    |   .
106 //  |    struct PerfJitBase;         |   .
107 //  |    uint64_t address_;          |   .
108 //  |    uint64_t entry_count_;      |   .
109 //  |    struct PerfJitDebugEntry;   |  .
110 //  |  }                             | .
111 //  +--------------------------------+
112 //  |  PerfJitCodeLoad               |
113 //     ...
114 //
115 struct PerfJitHeader {
116   uint32_t magic_;            // Characters "JiTD"
117   uint32_t version_;          // Header version
118   uint32_t size_;             // Total size of header
119   uint32_t elf_mach_target_;  // Elf mach target
120   uint32_t reserved_;         // Reserved, currently not used
121   uint32_t process_id_;       // Process ID of the JIT compiler
122   uint64_t time_stamp_;       // Timestamp when the header is generated
123   uint64_t flags_;            // Currently the flags are only used for choosing clock for timestamp,
124                               // we set it to 0 to tell perf that we use CLOCK_MONOTONIC clock.
125   static const uint32_t kMagic = 0x4A695444;  // "JiTD"
126   static const uint32_t kVersion = 1;
127 };
128 
129 // Each record starts with such basic information: event type, total size, and timestamp.
130 struct PerfJitBase {
131   enum PerfJitEvent {
132     // A jitted code load event.
133     // In ART JIT, it is used to log a new method is jit compiled and committed to jit-code-cache.
134     // Note that such kLoad event supports code cache GC in ART JIT.
135     // For every kLoad event recorded in jit-PID.dump and every perf sample recorded in perf.data,
136     // each event/sample has time stamp. In case code cache GC happens in ART JIT, and a new
137     // jitted method is committed to the same address of a previously deleted method,
138     // the time stamp information can help profiler to tell whether this sample belongs to the
139     // era of the first jitted method, or does it belong to the period of the second jitted method.
140     // JitCodeCache doesn't have to record any event on 'code delete'.
141     kLoad = 0,
142 
143     // A jitted code move event, i,e. a jitted code moved from one address to another address.
144     // It helps profiler to map samples to the right symbol even when the code is moved.
145     // In ART JIT, this event can help log such behavior:
146     // A jitted method is recorded in previous kLoad event, but due to some reason,
147     // it is moved to another address in jit-code-cache.
148     kMove = 1,
149 
150     // Logs debug line/column information.
151     kDebugInfo = 2,
152 
153     // Logs JIT VM end of life event.
154     kClose = 3
155   };
156   uint32_t event_;       // Must be one of the events defined in PerfJitEvent.
157   uint32_t size_;        // Total size of this event record.
158                          // For example, for kLoad event, size of the event record is:
159                          // sizeof(PerfJitCodeLoad) + method_name.size() + compiled code size.
160   uint64_t time_stamp_;  // Timestamp for the event.
161 };
162 
163 // Logs a jitted code load event (kLoad).
164 // In ART JIT, it is used to log a new method is jit compiled and commited to jit-code-cache.
165 struct PerfJitCodeLoad : PerfJitBase {
166   uint32_t process_id_;    // Process ID who performs the jit code load.
167                            // In ART JIT, it is the pid of the JIT compiler.
168   uint32_t thread_id_;     // Thread ID who performs the jit code load.
169                            // In ART JIT, it is the tid of the JIT compiler.
170   uint64_t vma_;           // Address of the code section. In ART JIT, because code_address_
171                            // uses absolute address, this field is 0.
172   uint64_t code_address_;  // Address where is jitted code is loaded.
173   uint64_t code_size_;     // Size of the jitted code.
174   uint64_t code_id_;       // Unique ID for each jitted code.
175 };
176 
177 // This structure is for source line/column mapping.
178 // Currently this feature is not implemented in ART JIT yet.
179 struct PerfJitDebugEntry {
180   uint64_t address_;      // Code address which maps to the line/column in source.
181   uint32_t line_number_;  // Source line number starting at 1.
182   uint32_t column_;       // Column discriminator, default 0.
183   const char name_[0];    // Followed by null-terminated name or \0xff\0 if same as previous.
184 };
185 
186 // Logs debug line information (kDebugInfo).
187 // This structure is for source line/column mapping.
188 // Currently this feature is not implemented in ART JIT yet.
189 struct PerfJitCodeDebugInfo : PerfJitBase {
190   uint64_t address_;              // Starting code address which the debug info describes.
191   uint64_t entry_count_;          // How many instances of PerfJitDebugEntry.
192   PerfJitDebugEntry entries_[0];  // Followed by entry_count_ instances of PerfJitDebugEntry.
193 };
194 
GetElfMach()195 static uint32_t GetElfMach() {
196 #if defined(__arm__)
197   static const uint32_t kElfMachARM = 0x28;
198   return kElfMachARM;
199 #elif defined(__aarch64__)
200   static const uint32_t kElfMachARM64 = 0xB7;
201   return kElfMachARM64;
202 #elif defined(__i386__)
203   static const uint32_t kElfMachIA32 = 0x3;
204   return kElfMachIA32;
205 #elif defined(__x86_64__)
206   static const uint32_t kElfMachX64 = 0x3E;
207   return kElfMachX64;
208 #else
209   UNIMPLEMENTED(WARNING) << "Unsupported architecture in JitLogger";
210   return 0;
211 #endif
212 }
213 
OpenMarkerFile()214 void JitLogger::OpenMarkerFile() {
215   int fd = jit_dump_file_->Fd();
216   // The 'perf inject' tool requires that the jit-PID.dump file
217   // must have a mmap(PROT_READ|PROT_EXEC) record in perf.data.
218   marker_address_ = mmap(nullptr, kPageSize, PROT_READ | PROT_EXEC, MAP_PRIVATE, fd, 0);
219   if (marker_address_ == MAP_FAILED) {
220     LOG(WARNING) << "Failed to create record in perf.data. JITed code profiling will not work.";
221     return;
222   }
223 }
224 
CloseMarkerFile()225 void JitLogger::CloseMarkerFile() {
226   if (marker_address_ != nullptr) {
227     munmap(marker_address_, kPageSize);
228   }
229 }
230 
WriteJitDumpDebugInfo()231 void JitLogger::WriteJitDumpDebugInfo() {
232   // In the future, we can add java source file line/column mapping here.
233 }
234 
WriteJitDumpHeader()235 void JitLogger::WriteJitDumpHeader() {
236   PerfJitHeader header;
237 
238   std::memset(&header, 0, sizeof(header));
239   header.magic_ = PerfJitHeader::kMagic;
240   header.version_ = PerfJitHeader::kVersion;
241   header.size_ = sizeof(header);
242   header.elf_mach_target_ = GetElfMach();
243   header.process_id_ = static_cast<uint32_t>(getpid());
244   header.time_stamp_ = art::NanoTime();  // CLOCK_MONOTONIC clock is required.
245   header.flags_ = 0;
246 
247   bool res = jit_dump_file_->WriteFully(reinterpret_cast<const char*>(&header), sizeof(header));
248   if (!res) {
249     LOG(WARNING) << "Failed to write profiling log. The 'perf inject' tool will not work.";
250   }
251 }
252 
OpenJitDumpLog()253 void JitLogger::OpenJitDumpLog() {
254   std::string pid_str = std::to_string(getpid());
255   std::string jitdump_filename = std::string(kLogPrefix) + "/jit-" + pid_str + ".dump";
256 
257   jit_dump_file_.reset(OS::CreateEmptyFile(jitdump_filename.c_str()));
258   if (jit_dump_file_ == nullptr) {
259     LOG(ERROR) << "Could not create jit dump file at " << jitdump_filename <<
260       " Are you on a user build? Perf only works on userdebug/eng builds";
261     return;
262   }
263 
264   OpenMarkerFile();
265 
266   // Continue to write jit-PID.dump file even above OpenMarkerFile() fails.
267   // Even if that means 'perf inject' tool cannot work, developers can still use other tools
268   // to map the samples in perf.data to the information (symbol,address,code) recorded
269   // in the jit-PID.dump file, and still proceed the jitted code analysis.
270   WriteJitDumpHeader();
271 }
272 
WriteJitDumpLog(JitCodeCache * code_cache,ArtMethod * method,bool osr)273 void JitLogger::WriteJitDumpLog(JitCodeCache* code_cache, ArtMethod* method, bool osr) {
274   if (jit_dump_file_ != nullptr) {
275     const void* code = osr ? code_cache->LookupOsrMethodHeader(method)->GetCode()
276                            : method->GetEntryPointFromQuickCompiledCode();
277     size_t code_size = code_cache->GetMemorySizeOfCodePointer(code);
278     std::string method_name = method->PrettyMethod();
279 
280     PerfJitCodeLoad jit_code;
281     std::memset(&jit_code, 0, sizeof(jit_code));
282     jit_code.event_ = PerfJitCodeLoad::kLoad;
283     jit_code.size_ = sizeof(jit_code) + method_name.size() + 1 + code_size;
284     jit_code.time_stamp_ = art::NanoTime();    // CLOCK_MONOTONIC clock is required.
285     jit_code.process_id_ = static_cast<uint32_t>(getpid());
286     jit_code.thread_id_ = static_cast<uint32_t>(art::GetTid());
287     jit_code.vma_ = 0x0;
288     jit_code.code_address_ = reinterpret_cast<uint64_t>(code);
289     jit_code.code_size_ = code_size;
290     jit_code.code_id_ = code_index_++;
291 
292     // Write one complete jitted method info, including:
293     // - PerfJitCodeLoad structure
294     // - Method name
295     // - Complete generated code of this method
296     //
297     // Use UNUSED() here to avoid compiler warnings.
298     UNUSED(jit_dump_file_->WriteFully(reinterpret_cast<const char*>(&jit_code), sizeof(jit_code)));
299     UNUSED(jit_dump_file_->WriteFully(method_name.c_str(), method_name.size() + 1));
300     UNUSED(jit_dump_file_->WriteFully(code, code_size));
301 
302     WriteJitDumpDebugInfo();
303   }
304 }
305 
CloseJitDumpLog()306 void JitLogger::CloseJitDumpLog() {
307   if (jit_dump_file_ != nullptr) {
308     CloseMarkerFile();
309     UNUSED(jit_dump_file_->Flush());
310     UNUSED(jit_dump_file_->Close());
311   }
312 }
313 
314 }  // namespace jit
315 }  // namespace art
316