Insert profiling instructions into s-p code to make each statement

be profiled separately.

Expand the time formats in i_s.profiling to wide enough for larger
numbers.

mysql-test/r/profiling.result

@@ -300,6 +300,100 @@ id
 select @@profiling;
 @@profiling
 1
+set session profiling = OFF;
+drop table if exists profile_log;
+Warnings:
+Note	1051	Unknown table 'profile_log'
+create table profile_log (how_many int);
+drop procedure if exists p1;
+drop procedure if exists p2;
+drop procedure if exists p3;
+create procedure p1 () modifies sql data begin set profiling = ON; select 'This p1 should show up in profiling'; insert into profile_log select count(*) from information_schema.profiling; end//
+create procedure p2() deterministic begin set profiling = ON; call p1(); select 'This p2 should show up in profiling'; end//
+create procedure p3 () reads sql data begin set profiling = ON; select 'This p3 should show up in profiling'; show profile; end//
+select count(*) as count_before_p1 from information_schema.profiling;
+count_before_p1
+535
+first call to p1
+call p1;
+This p1 should show up in profiling
+This p1 should show up in profiling
+select * from profile_log;
+how_many
+528
+second call to p1
+call p1;
+This p1 should show up in profiling
+This p1 should show up in profiling
+select * from profile_log;
+how_many
+528
+478
+third call to p1
+call p1;
+This p1 should show up in profiling
+This p1 should show up in profiling
+select * from profile_log;
+how_many
+528
+478
+443
+set session profiling = OFF;
+call p2;
+This p1 should show up in profiling
+This p1 should show up in profiling
+This p2 should show up in profiling
+This p2 should show up in profiling
+set session profiling = OFF;
+call p3;
+This p3 should show up in profiling
+This p3 should show up in profiling
+Status	Duration
+continuing inside routine	#
+checking permissions	#
+Opening tables	#
+init	#
+optimizing	#
+executing	#
+end	#
+query end	#
+closing tables	#
+show profiles;
+Query_ID	Duration	Query
+#	#	create table t3 (id int not null primary key)
+#	#	insert into t1 values (1), (2), (3)
+#	#	insert into t2 values (1), (2), (3)
+#	#	insert into t3 values (1), (2), (3)
+#	#	select * from t1
+#	#	delete from t1
+#	#	insert into t1 values (1), (2), (3)
+#	#	insert into t1 values (1), (2), (3)
+#	#	select * from t1
+#	#	select @@profiling
+#	#	create function f1() returns varchar(50) return 'hello'
+#	#	select @@profiling
+#	#	select @@profiling
+#	#	select 'This p1 should show up in profiling'
+#	#	insert into profile_log select count(*) from information_schema.profiling
+#	#	select * from profile_log
+#	#	SET profiling = ON
+#	#	select 'This p1 should show up in profiling'
+#	#	insert into profile_log select count(*) from information_schema.profiling
+#	#	select * from profile_log
+#	#	SET profiling = ON
+#	#	select 'This p1 should show up in profiling'
+#	#	insert into profile_log select count(*) from information_schema.profiling
+#	#	select * from profile_log
+#	#	SET profiling = ON
+#	#	select 'This p1 should show up in profiling'
+#	#	insert into profile_log select count(*) from information_schema.profiling
+#	#	select 'This p2 should show up in profiling'
+#	#	select 'This p3 should show up in profiling'
+#	#	show profile
+drop procedure if exists p1;
+drop procedure if exists p2;
+drop procedure if exists p3;
+drop table if exists profile_log;
 set session profiling = ON;
 drop table if exists t2;
 create table t2 (id int not null);

mysql-test/t/profiling.test

@@ -138,7 +138,7 @@ show profiles;
 
 ##  Verify that the various juggling of THD contexts doesn't affect profiling.
 
-##  Functions
+##  Functions and procedures
 set session profiling = ON;
 select @@profiling;
 create function f1() returns varchar(50) return 'hello';
@@ -146,6 +146,46 @@ select @@profiling;
 select * from t1 where id <> f1();
 select @@profiling;
 
+set session profiling = OFF;
+drop table if exists profile_log;
+create table profile_log (how_many int);
+
+--disable_warnings
+drop procedure if exists p1;
+drop procedure if exists p2;
+drop procedure if exists p3;
+--enable_warnings
+
+delimiter //;
+create procedure p1 () modifies sql data begin set profiling = ON; select 'This p1 should show up in profiling'; insert into profile_log select count(*) from information_schema.profiling; end//
+create procedure p2() deterministic begin set profiling = ON; call p1(); select 'This p2 should show up in profiling'; end//
+create procedure p3 () reads sql data begin set profiling = ON; select 'This p3 should show up in profiling'; show profile; end//
+delimiter ;//
+
+select count(*) as count_before_p1 from information_schema.profiling;
+--echo first call to p1
+call p1;
+select * from profile_log;
+--echo second call to p1
+call p1;
+select * from profile_log;
+--echo third call to p1
+call p1;
+select * from profile_log;
+set session profiling = OFF;
+call p2;
+set session profiling = OFF;
+--replace_column 2 #
+call p3;
+
+--replace_column 1 # 2 #
+show profiles;
+
+drop procedure if exists p1;
+drop procedure if exists p2;
+drop procedure if exists p3;
+drop table if exists profile_log;
+
 ##  Triggers
 set session profiling = ON;
 drop table if exists t2;

sql/sp_head.cc

@@ -1162,15 +1162,36 @@ sp_head::execute(THD *thd)
   */
   thd->spcont->callers_arena= &backup_arena;
 
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+  /* Discard the initial part of executing routines. */
+  thd->profiling.discard_current_query();
+#endif
   do
   {
     sp_instr *i;
     uint hip;			// Handler ip
 
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+    /* 
+     Treat each "instr" of a routine as discrete unit that could be profiled.
+     Profiling only records information for segments of code that set the
+     source of the query, and almost all kinds of instructions in s-p do not.
+    */
+    thd->profiling.finish_current_query();
+    thd->profiling.start_new_query("continuing inside routine");
+#endif
+
     i = get_instr(ip);	// Returns NULL when we're done.
     if (i == NULL)
+    {
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+      thd->profiling.discard_current_query();
+#endif
       break;
+    }
+
     DBUG_PRINT("execute", ("Instruction %u", ip));
+
     /* Don't change NOW() in FUNCTION or TRIGGER */
     if (!thd->in_sub_stmt)
       thd->set_time();		// Make current_time() et al work
@@ -1248,6 +1269,11 @@ sp_head::execute(THD *thd)
     }
   } while (!err_status && !thd->killed);
 
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+  thd->profiling.finish_current_query();
+  thd->profiling.start_new_query("tail end of routine");
+#endif
+
   /* Restore query context. */
 
   m_creation_ctx->restore_env(thd, saved_creation_ctx);
@@ -2725,6 +2751,10 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
 
   query= thd->query;
   query_length= thd->query_length;
+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)
+  /* This s-p instr is profilable and will be captured. */
+  thd->profiling.set_query_source(m_query.str, m_query.length);
+#endif
   if (!(res= alloc_query(thd, m_query.str, m_query.length)) &&
       !(res=subst_spvars(thd, this, &m_query)))
   {

sql/sql_profile.cc

@@ -33,7 +33,9 @@
 #include "my_sys.h"
 
 #define TIME_FLOAT_DIGITS 9
-#define TIME_I_S_DECIMAL_SIZE (6*100)+6 /**< two vals encoded: (dec*100)+len */
+/** two vals encoded: (dec*100)+len */
+#define TIME_I_S_DECIMAL_SIZE (TIME_FLOAT_DIGITS*100)+(TIME_FLOAT_DIGITS-3)
+
 #define MAX_QUERY_LENGTH 300
 
 /* Reserved for systems that can't record the function name in source. */