]>
Commit | Line | Data |
---|---|---|
d0da6fe5 ER |
1 | diff -r 92e70e675363 patch_info/profiling_slow.info |
2 | --- /dev/null Thu Jan 01 00:00:00 1970 +0000 | |
3 | +++ b/patch_info/profiling_slow.info Mon Jun 01 00:50:00 2009 -0700 | |
4 | @@ -0,0 +1,9 @@ | |
5 | +File=profiling_slow.info | |
6 | +Name=profiling from SHOW PROFILE to slow.log | |
7 | +Version=1.0 | |
8 | +Author=Percona <info@percona.com> | |
9 | +License=GPL | |
10 | +Comment= | |
11 | +Changelog | |
12 | +2009-05-18 | |
13 | +Initial implementation | |
14 | diff -r 92e70e675363 sql/log.cc | |
15 | --- a/sql/log.cc Mon Jun 01 00:48:56 2009 -0700 | |
16 | +++ b/sql/log.cc Mon Jun 01 00:50:00 2009 -0700 | |
17 | @@ -2402,6 +2402,11 @@ | |
18 | tmp_errno=errno; | |
19 | } | |
20 | } | |
21 | + | |
22 | +#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER) | |
23 | + thd->profiling.print_current(&log_file); | |
24 | +#endif | |
25 | + | |
26 | if (thd->db && strcmp(thd->db,db)) | |
27 | { // Database changed | |
28 | if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1) | |
29 | diff -r 92e70e675363 sql/mysqld.cc | |
30 | --- a/sql/mysqld.cc Mon Jun 01 00:48:56 2009 -0700 | |
31 | +++ b/sql/mysqld.cc Mon Jun 01 00:50:00 2009 -0700 | |
32 | @@ -5052,6 +5052,8 @@ | |
33 | OPT_PORT_OPEN_TIMEOUT, | |
34 | OPT_MERGE, | |
35 | OPT_PROFILING, | |
36 | + OPT_PROFILING_SERVER, | |
37 | + OPT_PROFILING_USE_GETRUSAGE, | |
38 | OPT_SLOW_LOG, | |
39 | OPT_SLOW_QUERY_LOG_FILE, | |
40 | OPT_USE_GLOBAL_LONG_QUERY_TIME, | |
41 | @@ -5675,6 +5677,16 @@ | |
42 | (gptr*) &global_system_variables.profiling_history_size, | |
43 | (gptr*) &max_system_variables.profiling_history_size, | |
44 | 0, GET_ULONG, REQUIRED_ARG, 15, 0, 100, 0, 0, 0}, | |
45 | + {"profiling_server", OPT_PROFILING_SERVER, | |
46 | + "Enable profiling of all threads", | |
47 | + (gptr*) &global_system_variables.profiling_server, | |
48 | + (gptr*) &max_system_variables.profiling_server, 0, GET_BOOL, | |
49 | + OPT_ARG, 0, 0, 0, 0, 0, 0 }, | |
50 | + {"profiling_use_getrusage", OPT_PROFILING_USE_GETRUSAGE, | |
51 | + "Enable getrusage function call for profiling", | |
52 | + (gptr*) &global_system_variables.profiling_use_getrusage, | |
53 | + (gptr*) &max_system_variables.profiling_use_getrusage, 0, GET_BOOL, | |
54 | + OPT_ARG, 0, 0, 0, 0, 0, 0 }, | |
55 | #endif | |
56 | {"relay-log", OPT_RELAY_LOG, | |
57 | "The location and name to use for relay logs.", | |
58 | diff -r 92e70e675363 sql/set_var.cc | |
59 | --- a/sql/set_var.cc Mon Jun 01 00:48:56 2009 -0700 | |
60 | +++ b/sql/set_var.cc Mon Jun 01 00:50:00 2009 -0700 | |
61 | @@ -592,6 +592,10 @@ | |
62 | ulonglong(OPTION_PROFILING)); | |
63 | static sys_var_thd_ulong sys_profiling_history_size("profiling_history_size", | |
64 | &SV::profiling_history_size); | |
65 | +static sys_var_thd_bool sys_profiling_server("profiling_server", | |
66 | + &SV::profiling_server); | |
67 | +static sys_var_thd_bool sys_profiling_use_getrusage("profiling_use_getrusage", | |
68 | + &SV::profiling_use_getrusage); | |
69 | #endif | |
70 | ||
71 | /* Local state variables */ | |
72 | @@ -764,6 +768,8 @@ | |
73 | #ifdef ENABLED_PROFILING | |
74 | &sys_profiling, | |
75 | &sys_profiling_history_size, | |
76 | + &sys_profiling_server, | |
77 | + &sys_profiling_use_getrusage, | |
78 | #endif | |
79 | &sys_pseudo_thread_id, | |
80 | &sys_query_alloc_block_size, | |
81 | @@ -1094,6 +1100,8 @@ | |
82 | #ifdef ENABLED_PROFILING | |
83 | {sys_profiling.name, (char*) &sys_profiling, SHOW_SYS}, | |
84 | {sys_profiling_history_size.name, (char*) &sys_profiling_history_size, SHOW_SYS}, | |
85 | + {sys_profiling_server.name, (char*) &sys_profiling_server, SHOW_SYS}, | |
86 | + {sys_profiling_use_getrusage.name, (char*) &sys_profiling_use_getrusage, SHOW_SYS}, | |
87 | #endif | |
88 | {"protocol_version", (char*) &protocol_version, SHOW_INT}, | |
89 | {sys_query_alloc_block_size.name, (char*) &sys_query_alloc_block_size, | |
90 | diff -r 92e70e675363 sql/sql_class.h | |
91 | --- a/sql/sql_class.h Mon Jun 01 00:48:56 2009 -0700 | |
92 | +++ b/sql/sql_class.h Mon Jun 01 00:50:00 2009 -0700 | |
93 | @@ -550,6 +550,8 @@ | |
94 | ulong optimizer_search_depth; | |
95 | ulong preload_buff_size; | |
96 | ulong profiling_history_size; | |
97 | + my_bool profiling_server; | |
98 | + my_bool profiling_use_getrusage; | |
99 | ulong query_cache_type; | |
100 | ulong log_slow_rate_limit; | |
101 | ulong read_buff_size; | |
102 | diff -r 92e70e675363 sql/sql_profile.cc | |
103 | --- a/sql/sql_profile.cc Mon Jun 01 00:48:56 2009 -0700 | |
104 | +++ b/sql/sql_profile.cc Mon Jun 01 00:50:00 2009 -0700 | |
105 | @@ -221,9 +221,22 @@ | |
106 | */ | |
107 | void PROF_MEASUREMENT::collect() | |
108 | { | |
109 | + struct timespec tp; | |
110 | time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */ | |
111 | #ifdef HAVE_GETRUSAGE | |
112 | - getrusage(RUSAGE_SELF, &rusage); | |
113 | + if ((profile->get_profiling())->enabled_getrusage()) | |
114 | + getrusage(RUSAGE_SELF, &rusage); | |
115 | +#endif | |
116 | + | |
117 | +#ifdef HAVE_CLOCK_GETTIME | |
118 | + if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp))) | |
119 | + { | |
120 | + cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec; | |
121 | + } | |
122 | + else | |
123 | + { | |
124 | + cpu_time_usecs= 0; | |
125 | + } | |
126 | #endif | |
127 | } | |
128 | ||
129 | @@ -341,7 +354,7 @@ | |
130 | finish_current_query(); | |
131 | } | |
132 | ||
133 | - enabled= (((thd)->options & OPTION_PROFILING) != 0); | |
134 | + enabled= (((thd)->options & OPTION_PROFILING) != 0) || ( thd->variables.profiling_server ); | |
135 | ||
136 | if (! enabled) DBUG_VOID_RETURN; | |
137 | ||
138 | @@ -379,7 +392,8 @@ | |
139 | status_change("ending", NULL, NULL, 0); | |
140 | ||
141 | if ((enabled) && /* ON at start? */ | |
142 | - ((thd->options & OPTION_PROFILING) != 0) && /* and ON at end? */ | |
143 | + (((thd->options & OPTION_PROFILING) != 0) || | |
144 | + (thd->variables.profiling_server)) && /* and ON at end? */ | |
145 | (current->query_source != NULL) && | |
146 | (! current->entries.is_empty())) | |
147 | { | |
148 | @@ -480,6 +494,88 @@ | |
149 | DBUG_VOID_RETURN; | |
150 | } | |
151 | ||
152 | +bool PROFILING::enabled_getrusage() | |
153 | +{ | |
154 | + return thd->variables.profiling_use_getrusage; | |
155 | +} | |
156 | + | |
157 | +/** | |
158 | + Print output for current query to file | |
159 | +*/ | |
160 | + | |
161 | +int PROFILING::print_current(IO_CACHE *log_file) | |
162 | +{ | |
163 | + DBUG_ENTER("PROFILING::print_current"); | |
164 | + ulonglong row_number= 0; | |
165 | + char query_time_buff[22+7]; | |
166 | + char query_cpu_time_buff[22+7]; | |
167 | + | |
168 | + QUERY_PROFILE *query; | |
169 | + /* Get current query */ | |
170 | + if (current == NULL) | |
171 | + { | |
172 | + DBUG_RETURN(0); | |
173 | + } | |
174 | + | |
175 | + query= current; | |
176 | + | |
177 | + my_b_printf(log_file, "# PROFILE_VALUES "); | |
178 | + | |
179 | + void *entry_iterator; | |
180 | + PROF_MEASUREMENT *entry, *previous= NULL, *first= NULL; | |
181 | + /* ...and for each query, go through all its state-change steps. */ | |
182 | + for (entry_iterator= query->entries.new_iterator(); | |
183 | + entry_iterator != NULL; | |
184 | + entry_iterator= query->entries.iterator_next(entry_iterator), | |
185 | + previous=entry, row_number++) | |
186 | + { | |
187 | + entry= query->entries.iterator_value(entry_iterator); | |
188 | + | |
189 | + /* Skip the first. We count spans of fence, not fence-posts. */ | |
190 | + if (previous == NULL) {first= entry; continue;} | |
191 | + | |
192 | + if (thd->lex->orig_sql_command == SQLCOM_SHOW_PROFILE) | |
193 | + { | |
194 | + /* | |
195 | + We got here via a SHOW command. That means that we stored | |
196 | + information about the query we wish to show and that isn't | |
197 | + in a WHERE clause at a higher level to filter out rows we | |
198 | + wish to exclude. | |
199 | + | |
200 | + Because that functionality isn't available in the server yet, | |
201 | + we must filter here, at the wrong level. Once one can con- | |
202 | + struct where and having conditions at the SQL layer, then this | |
203 | + condition should be ripped out. | |
204 | + */ | |
205 | + if (thd->lex->profile_query_id == 0) /* 0 == show final query */ | |
206 | + { | |
207 | + if (query != last) | |
208 | + continue; | |
209 | + } | |
210 | + else | |
211 | + { | |
212 | + if (thd->lex->profile_query_id != query->profiling_query_id) | |
213 | + continue; | |
214 | + } | |
215 | + } | |
216 | + | |
217 | + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-previous->time_usecs)/(1000.0*1000)); | |
218 | + snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-previous->cpu_time_usecs)/(1000.0*1000*1000)); | |
219 | + my_b_printf(log_file, "%s: %s (cpu: %s), ", previous->status, query_time_buff, query_cpu_time_buff); | |
220 | + | |
221 | + } | |
222 | + | |
223 | + my_b_printf(log_file, "\n"); | |
224 | + if ((entry != NULL) && (first != NULL)) | |
225 | + { | |
226 | + snprintf(query_time_buff, sizeof(query_time_buff), "%.6f", (entry->time_usecs-first->time_usecs)/(1000.0*1000)); | |
227 | + snprintf(query_cpu_time_buff, sizeof(query_cpu_time_buff), "%.6f", (entry->cpu_time_usecs-first->cpu_time_usecs)/(1000.0*1000*1000)); | |
228 | + my_b_printf(log_file, "# PROFILE_TOTALS Total: %s (cpu: %s)\n", query_time_buff, query_cpu_time_buff); | |
229 | + } | |
230 | + | |
231 | + DBUG_RETURN(0); | |
232 | +} | |
233 | + | |
234 | /** | |
235 | Fill the information schema table, "query_profile", as defined in show.cc . | |
236 | There are two ways to get to this function: Selecting from the information | |
237 | diff -r 92e70e675363 sql/sql_profile.h | |
238 | --- a/sql/sql_profile.h Mon Jun 01 00:48:56 2009 -0700 | |
239 | +++ b/sql/sql_profile.h Mon Jun 01 00:50:00 2009 -0700 | |
240 | @@ -193,6 +193,7 @@ | |
241 | unsigned int line; | |
242 | ||
243 | double time_usecs; | |
244 | + double cpu_time_usecs; | |
245 | char *allocated_status_memory; | |
246 | ||
247 | void set_label(const char *status_arg, const char *function_arg, | |
248 | @@ -243,6 +244,11 @@ | |
249 | ||
250 | /* Show this profile. This is called by PROFILING. */ | |
251 | bool show(uint options); | |
252 | + | |
253 | +public: | |
254 | + | |
255 | + inline PROFILING * get_profiling() { return profiling; }; | |
256 | + | |
257 | }; | |
258 | ||
259 | ||
260 | @@ -288,9 +294,11 @@ | |
261 | ||
262 | /* SHOW PROFILES */ | |
263 | bool show_profiles(); | |
264 | + bool enabled_getrusage(); | |
265 | ||
266 | /* ... from INFORMATION_SCHEMA.PROFILING ... */ | |
267 | int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond); | |
268 | + int print_current(IO_CACHE *log_file); | |
269 | }; | |
270 | ||
271 | # endif /* HAVE_PROFILING */ |