1 // © 2021 Qualcomm Innovation Center, Inc. All rights reserved.
2 //
3 // SPDX-License-Identifier: BSD-3-Clause
4
5 #include <assert.h>
6 #include <hyptypes.h>
7 #include <stdatomic.h>
8 #include <string.h>
9
10 #include <hypconstants.h>
11 #include <hypregisters.h>
12
13 #include <compiler.h>
14 #include <cpulocal.h>
15 #include <platform_timer.h>
16 #include <trace.h>
17 #include <util.h>
18
19 #include <events/log.h>
20
21 #include <asm/cache.h>
22 #include <asm/cpu.h>
23 #include <asm/prefetch.h>
24
25 #include "event_handlers.h"
26 #include "string_util.h"
27 #include "trace_helpers.h"
28
29 // FIXME: the log temporary buffer is placed on the stack
30 // Note: thread_stack_size_default = 4096
31 #define LOG_TIMESTAMP_BUFFER_SIZE 24U
32 #define LOG_ENTRY_BUFFER_SIZE 256U
33
34 extern char hyp_log_buffer[];
35 char hyp_log_buffer[LOG_BUFFER_SIZE];
36
37 static_assert((size_t)LOG_BUFFER_SIZE > LOG_ENTRY_BUFFER_SIZE,
38 "LOG_BUFFER_SIZE too small");
39
40 // Global visibility - for debug
41 extern log_control_t hyp_log;
42
43 log_control_t hyp_log = { .log_magic = LOG_MAGIC,
44 .head = 0,
45 .buffer_size = LOG_BUFFER_SIZE,
46 .log_buffer = hyp_log_buffer };
47
48 void
log_init(void)49 log_init(void)
50 {
51 register_t flags = 0U;
52 TRACE_SET_CLASS(flags, LOG_BUFFER);
53 trace_set_class_flags(flags);
54
55 assert_debug(hyp_log.buffer_size == (index_t)LOG_BUFFER_SIZE);
56 }
57
58 void
log_standard_handle_trace_log(trace_id_t id,trace_action_t action,const char * fmt,register_t arg0,register_t arg1,register_t arg2,register_t arg3,register_t arg4)59 log_standard_handle_trace_log(trace_id_t id, trace_action_t action,
60 const char *fmt, register_t arg0, register_t arg1,
61 register_t arg2, register_t arg3, register_t arg4)
62 {
63 index_t next_idx, prev_idx, orig_idx;
64 size_result_t ret;
65 size_t entry_size, timestamp_size;
66 char entry_buf[LOG_ENTRY_BUFFER_SIZE];
67
68 // Add the data to the log buffer only if:
69 // - The requested action is logging, and logging is enabled
70 bool log_action = ((action == TRACE_ACTION_LOG) ||
71 (action == TRACE_ACTION_TRACE_AND_LOG));
72 register_t class_flags = trace_get_class_flags();
73 if (compiler_unexpected(
74 ((!log_action ||
75 ((class_flags & TRACE_CLASS_BITS(LOG_BUFFER)) == 0U))))) {
76 goto out;
77 }
78
79 // Add the time-stamp and core number
80 // We could use platform_convert_ticks_to_ns() here, but the resulting
81 // values will be too big and unwieldy to use. Since log formatting is a
82 // slow process anyway, might as well add some nice time-stamps.
83 ticks_t now = platform_timer_get_current_ticks();
84 nanoseconds_t ns = platform_timer_convert_ticks_to_ns(now);
85
86 microseconds_t usec = ns / (microseconds_t)1000;
87 uint64_t sec = usec / TIMER_MICROSECS_IN_SECOND;
88
89 ret = snprint(entry_buf, LOG_TIMESTAMP_BUFFER_SIZE,
90 "{:d} {:4d}.{:06d} ", cpulocal_get_index_unsafe(), sec,
91 usec % TIMER_MICROSECS_IN_SECOND, 0, 0);
92 if (ret.e == ERROR_STRING_TRUNCATED) {
93 // The truncated string will have a NULL terminator, remove it
94 timestamp_size = LOG_TIMESTAMP_BUFFER_SIZE - 1U;
95 } else if (ret.e != OK) {
96 // Should not happen
97 goto out;
98 } else {
99 // Do not count the NULL character since we will write over it
100 // shortly.
101 timestamp_size = ret.r;
102 }
103
104 // Add the log message after the time-stamp
105 ret = snprint(entry_buf + timestamp_size,
106 LOG_ENTRY_BUFFER_SIZE - timestamp_size, fmt, arg0, arg1,
107 arg2, arg3, arg4);
108 if (ret.e == ERROR_STRING_TRUNCATED) {
109 entry_size = LOG_ENTRY_BUFFER_SIZE;
110 } else if ((ret.e == ERROR_STRING_MISSING_ARGUMENT) || (ret.r == 0U)) {
111 goto out;
112 } else {
113 entry_size = timestamp_size + ret.r + 1U;
114 assert(entry_size <= LOG_ENTRY_BUFFER_SIZE);
115 }
116
117 const index_t buffer_size = (index_t)LOG_BUFFER_SIZE;
118
119 // Inform the subscribers of the entry without the time-stamp
120 trigger_log_message_event(id, entry_buf + timestamp_size);
121
122 // Atomically update the index first
123 orig_idx = atomic_fetch_add_explicit(&hyp_log.head, entry_size,
124 memory_order_relaxed);
125 prev_idx = orig_idx;
126 while (compiler_unexpected(prev_idx >= buffer_size)) {
127 prev_idx -= buffer_size;
128 }
129
130 next_idx = orig_idx + (index_t)entry_size;
131 // If we wrap, something is really wrong
132 assert(next_idx > orig_idx);
133
134 if (compiler_unexpected(next_idx >= buffer_size)) {
135 index_t old_idx = next_idx;
136
137 while (next_idx >= buffer_size) {
138 next_idx -= buffer_size;
139 }
140
141 // Try to reduce the index in the shared variable so it is no
142 // longer overflowed. We don't care if it fails because that
143 // means somebody else has done it concurrently.
144 (void)atomic_compare_exchange_strong_explicit(
145 &hyp_log.head, &old_idx, next_idx, memory_order_relaxed,
146 memory_order_relaxed);
147 }
148
149 prefetch_store_stream(&hyp_log.log_buffer[prev_idx]);
150
151 size_t buf_remaining = (size_t)buffer_size - (size_t)prev_idx;
152
153 // Copy the whole entry if it fits
154 if (compiler_expected(buf_remaining >= entry_size)) {
155 (void)memcpy(&hyp_log.log_buffer[prev_idx], entry_buf,
156 entry_size);
157 cache_clean_range(&hyp_log.log_buffer[prev_idx], entry_size);
158 } else {
159 // Otherwise copy the first bit of entry to the tail of the
160 // buffer and wrap to the start for the remainder.
161 size_t first_part = buf_remaining;
162 (void)memcpy(&hyp_log.log_buffer[prev_idx], entry_buf,
163 first_part);
164 cache_clean_range(&hyp_log.log_buffer[prev_idx], first_part);
165
166 size_t second_part = entry_size - first_part;
167
168 (void)memcpy(&hyp_log.log_buffer[0], entry_buf + first_part,
169 second_part);
170 cache_clean_range(&hyp_log.log_buffer[0], second_part);
171 }
172 out:
173 // Nothing to do
174 return;
175 }
176