 Yeah, my name is Jan Wieck. I joined the Postgres open source community in 1996 by contributing the fixing of the Rewriter, the rule Rewriter that implements views. I had used Postgres two years before that already. And over the years, I contributed things like PLTICL, PLPG SQL, which we're talking about today. Things like the numeric data type, toast, foreign keys. So pretty much all the things that cause headaches for you today. You can pretty much, if it hurts, think about me. Yep. Today, I want to talk about profiling. And in software engineering, blah, blah Wikipedia explains wonderfully in detail what profiling is. But when we look at database profiling, unless you are a core developer down in the engine and try to optimize the access paths of the executor and stuff like that, all that is irrelevant to you. What you really want to know is, why the heck is my query slow? And which of them is it? You know, you don't have an application that throws three different queries at a database. You usually have something a little bit more complex. So finding that is the topic of profiling. And Postgres has a lot of system views and statistics that it can collect for you. The statistics collector is also one of my original works. Now, it was originally designed to help you exactly find missing indexes and stuff like that. I just never got around to really doing it. So Postgres collects all these statistics and over the years, we became completely dependent on it because vacuum wouldn't run or auto vacuum wouldn't run properly otherwise. But really using them for profiling and finding out which of your queries are slow, it doesn't do. But along came other tools like the Postgres logs that can be turned on to log your queries with execution time and all of that and extensions like PGstat statements. Who of you has ever used PGstat statements? That's quite a few. And was it useful? Yes. Good, even better. But for a lot of this stuff, now PGstat statements is really impressive. Very good tool. I love it too, to find slow queries. The Postgres logs, not so useful. Yeah, you will see the outlier, the query that all of a sudden takes five minutes when it shouldn't. But to really use third-party tools like PG Badger, who has used PG Badger? You guys are an amazing crowd. You use all this stuff. I'm proud of you. But who had problems with running PG Badger because of its excessive logging? Yep, we know that. Seen that too. So if you really want to find out what's going on on your database and analyze that with PG Badger, you have to crank up logging to levels that are just unsustainable in production. Yeah, you can't have a system that within an hour writes 400 gigabytes of logs. That's not sustainable. And then let PG Badger analyze those for two days, just for one hour. I've done this, it's hopeless. Yeah, and then you have queries that you simply don't find that way. A query that executes for 60 milliseconds, well, if you have logs min duration statement set to 10 seconds, it's never showing up. But if that query is executed 10,000 times, 60 milliseconds, that's 10 minutes of runtime. So small things in big numbers can hurt very much. Ever took down your pants and sat in an anthill? Small things in big numbers, they really hurt. So, sorry. So with that, I want to do a little side note. Now that I know you are people who are using PG Badger and PG Stat Statements, how many of you have actually profiled your application, the query runtimes and built a baseline before you ever had a performance problem? One. Dave. Yes. It's obvious. If you don't have a baseline, if you don't know what's normal, you don't know what's out of whack when you have a performance problem. So please keep it that way, don't profile, because that's my job as a consultant, yeah? Seriously, we need to change that. You need to establish performance baselines so that when you have a problem, I don't have to hunt for weeks after them. Now, all of that, all of these tools work more or less good if you are looking for application queries that are slow, yeah? If you have an application query that's really churning for minutes, you will find it with turning on log min duration statement. And PG Stat statements is even better for that. Now, some of them, like auto-analyze, those tools I haven't even mentioned yet, because whoever used auto-analyze, you turned it on in production. And how fast did you turn it off again? Yes, it's horrible. It's useless for this kind of stuff. So now there is an additional set of problems when it comes to finding slow queries or problems inside of PLPG SQL. And yeah, you're nodding. You've been there. I can see it. So in order to understand that, a little bit of background about how PLPG SQL works internally is really helpful. PLPG SQL was born out of necessity because I had created PLTICL and nobody liked it. So everybody was nagging for a language that is more like PLSQL and natively built in to Postgres. And to get rid of that nagging, I created PLPG SQL. Quick and dirty and nothing fancy. Anyhow, so it's just another loadable language. And what happens is, if you have this language defined and a function should be called in that language, the Postgres function manager simply loads the language handler and tells it, yeah, execute that for me. Postgres itself has no knowledge about what's internally going on in your procedural languages. For example, if you have PLPURL or PLPython has absolutely no knowledge about the internals of that thing, which is good because that's why we have so many different languages. So now the language handler is called, it looks at the PG PROC entry where it finds all the call arguments and the return type and of course, the function source code. And on the first call of that function, it parses that function source code the first call within your session that is. So every new database connection does the same thing for all the functions called again and again, bad design. Yes, I admit that. Anyhow, so now it looks at that source code and it interprets all the control structures. Your if, while, all these things, all these control structures. The SQL in it by itself, it doesn't really parse, it just looks for where's the end of the SQL statement and keeps it in the statement as a string. And it builds that way, this nested tree of C memory structures that contain these statements and pointers to other statements. So if you have, for example, a while loop, there is this SQL statement, there is this SQL statement in there that returns a Boolean value, whether the while loop should be traversed again, and then there is a list of other PLPG SQL statements that's the loop body, pretty simple. And then it still has all these SQL statements just as a string in there. And there are more SQL statements than hits the I immediately. An assignment like that is actually internally a select some parameter times 100. Yeah? So it turns this into a select statement. You could actually, and very few people know this, you could have a from clause and a where clause and all of that in that expression would perfectly fine swallow it and it would work. Totally fine, anyhow. So now it comes to the execution. And this is the reason why it kept this as an SQL statement. If you have a very complex function, you don't wanna go through parsing, planning, optimizing 500 different SQL statements of this gigantic function if it just doesn't if at the beginning in an exit or return. That's totally wasted effort. Let that parsing and planning of the SQL statement happen when it's needed. And then the first time the SQL statement is called, it's saved as a saved SPI plan and forever only executed. So that whole parsing planning only happens once. I will now go to a little example that is based on the benchmark SQL benchmark. Benchmark SQL is a TPCC style benchmark. It's open source. It's a Java application that more or less implements TPCC. I'm not exactly there yet, but we'll get there. Anyhow, now like the more known PG bench, it has a history table where every time an order is placed or a payment happens, a row is inserted. The main difference in this little case for the history table is, well, the customer that it references has a three column primary key instead of one. And if we would sum up the balance or all the history rows that belong to a customer, we would of course see the statement if enabled in PG stat statements. We would also eventually see it in PG log. And since the history table has zero indexes, it would be a sequential scan and all the alarm bells and whistles of our monitoring would go off and we would know, oh, something is going wrong here. We need an index or something like that, yeah? That would all happen. So now let's create a PLPG SQL function that takes the primary key of the customer as input parameters and then does exactly that same query basically to get the balance of the customer. Simply enough, right? And of course for ease of use, we create a view. The name of the view was chosen just randomly. Yep, that spits out the balance as of the customer row and the balance that results when summing up the history rows. They should always match, yes? Now we of course know certain things about this. First of all, we know that the history table is all ever growing and we know that there is no index on that table that every single customer lookup is its own separate sequential scan over the history table. That affects performance in the future. I guarantee it, yeah? And now I planted this, very obvious. So I put a big elephant in the middle of the room and now I show you how to find it. That's not very sophisticated but for the sake of presenting, it's a very useful tool. Now, since this thing is buried in a PLPG SQL function, if I select from that view, all that shows up in the Postgres logs is the select from the view. The Postgres logs have no mechanism to show you the statements that happen inside of the stored procedure or function that it doesn't have. That's a lie or slight exaggeration. You could enable auto-explain. Then it will show you that thing and it will take down your database server in no time. Yeah, so yeah. So now that thing is there and that down here, that's the real thing that we are interested in, this query, because what happens during the execution of the view query is we are executing this in the Postgres main engine. Postgres main engine needs to call this function, getCustomerBalance, that invokes the PLPG SQL call handler, which then does an SPI exec. Slightly simplified, it does something else but in essence that's what's happening and that query here is not logged. Even if you say PG, now you can't see this in the view PGStat statements, yeah? For that you have to alter the configuration and it will remember all the queries that happen in your functions and stored procedures as well. There'll be a lot of statements, so you better up the memory allowance for PGStat statements as well, but it works. Now let's really leave this out with auto explain. One thing is that the query there that you will see in PGStat statements is not identical to the one that's in your stored procedure, yeah? So that thing, now if we only have two or three functions, yeah, that works. If you have more than that, like a couple hundred with thousands of lines of code, it's not a needle in a haystack. It's a needle in the remains of a haystack that went through the digestive system of an elephant, yeah? That's what you're looking into. Nobody finds it fun to dig around in that stuff. Don't do it, yeah? Because now this is what you see in PGStat statements. That's the query that you see there. Remember what the stored procedure looked like? Well, let's see. There it is. That query basically has this inter-part replaced with blanks. Great, isn't it? Yeah. And now you're looking for that. And this is normally not your problem query. I've seen queries in stored procedures that go over 80, 100, 200 lines with five CTEs. Try to find that one in there. Yeah, it's really no fun. So yeah, this is a simple example and we could have found that easily by looking at the view, but in the real world, things are different. The first customer I ever used the new PL profiler on has a slightly different schema. I was confronted with 1,800 tables, 13,000 indexes, 600 PLPG SQL functions with over 100,000 lines of code, PL code. The whole business logic is in PLPG SQL, everything. All the application is doing is calling a PLPG SQL function that goes recursively over many, many, many other functions and returns a value, basically. Very nice, find that, yeah? Which of all these thousands of queries, literally, is causing your problem. And for the fun of it, I looked at the database stats where no sequential scans happening. Nothing like that. And yeah, our on call and remote DVAs had been looking at that problem for quite a while and were just as clueless as before. Nobody could really tackle it. So now, let's talk a little bit about the architecture of the PL profiler. The PL profiler is really two things. One is an extension. It's a shared library that can be loaded into the back end with functions and all that. So regular Postgres extension. And the other one is a command line utility that is used to drive the whole profiler. The command line utility is also separated into the command line part and a Python class. So it should be very easy to integrate this into other tools, like GUIs and stuff like that, yeah? The extension is using debug hooks in the PL-PG SQL executor. And the hooks will get invoked when certain things happening in PL-PG SQL. So every time a function is entered or function exits, one of these hooks is called. Likewise, when a statement is called and when a statement exits, a hook is called. And that way, by capturing time stamps basically from before and after, I can sum up how much time is spent where in the whole thing. And so using these callbacks, the profiler now collects three different things. One is a per call stack number of calls and time spent in there. I will talk about call stacks or call graphs as they are also called on the next slide a little bit. The other is per function numbers. How often the function got called, how much time is spent in there. And then inside of each function for every little statement. How often was it traversed? So if you have a loop in there that traverses a thousand times, function is called five times that loop will have a counter of 5,000 executions. Yep, pretty simple. And then as I said, the command line utility we use to control all that, extract the data that's collected and build a humanly readable report out of it. So what is a call graph? A call graph is basically your current call stack, your back trace. If you ever used GDB, the back trace is your call stack, right? It shows you where exactly in the whole process the program is executing and how it got there. So function A for calls, function C calls, function F. That's how I got there, that's one call stack. If there is another path to get to F via ABF, then that's a different call stack. Different call stacks often have very different performance metrics, yeah? Now what do we do with call graphs? Something cool. Who has ever seen flame graphs? Yeah, now it gets really cool. Or maybe hot. This is the actual call graph of that customer database that I was talking about, this 1800, 13,000 indexes, blah, blah, yeah? That's the call graph. Now there are two things to mention. So first of all, this was the function called originally and then recursively it called all these functions. One thing that sticks out here is that get new sequence is reached through this path and through this path. And together these two blocks, the width is basically the execution time here, the cumulative execution time, how much was spent inside of this sub-function. Sub-function, well if I add these two together it's like 75 to 80% of the whole outer function call. So that is the function that I'm really interested in. All the other stuff uses very little time by itself. Those are not my candidates, that one, get new sequence is the one. Sorry for the blur, but it is a real world customer proprietary code that I can't show you, yeah? What I can show you is of course, much easier to understand example. I will build another function on top of the one that we already have. Just to tell you what the real culprit here was, what it ultimately boiled down to was that function get new sequence was doing a select from a relatively small table, just a couple thousand rows. But the rows were rather wide. And here was when I looked at it, I saw the query, I threw it into explain analyze and index scan over the primary key. Who would ever think that's a problem? Well, it turned out that the where clause missed the first column of the primary key. And thanks that Postgres is so smart, it did an index scan, scanning the whole index sequentially and building a bitmap to find the candidate rows. We created one additional index on the database and the whole application jumped by factor two plus in performance. Happy customer, I can tell you. So anyhow, back to our example, I wanna show you the output of the profiler finally, yeah? So we create another function that now gives us the entire sum of the history table. And now everybody here knows enough about SQL to tell that's nonsense. Yeah, you don't do it this way, but have you ever worked with Node.js programmers? Man, there is an API, I use it. And this is the result, yeah? If you look at their ORMs, this is what you will find. And this is, don't fight them. It's just not worth it, yeah? Change their code in the background and be happy with it. It's, no, okay, enough about that. So anyhow, we know already that this is bad and since we placed it there on purpose, we know how this should look like, yeah? But since I showed you the real world example before, you know, in the real world, it's hard to find those things, yeah? When it's deep, nine core levels deep and yeah, you're looking for an index scan, great. And that was one of these 60 millisecond index scans. Yeah, it was just executed 100,000 times. Anyhow, so with that in place, we now use the profiler command line utility. And we say run against my benchmark database, execute this query and create a report, test1.html, simple enough. This thing will turn on profiling only in this session that it establishes itself. So it does not affect the global database. And it will run this SQL statement and then write the test output. And voila, we see what we pretty much expected. We have a function that's rather expensive compared to a different one. Well, you would have expected, eventually, that the ratio between the two is a little different. This is because it's a small database still. And since this is only one invocation of the outer function, and then however many customers there are of the inner function, they pay the full price of parsing, planning, optimizing all the SQL statements in them. That's a skewed picture. Yeah, but anyhow, we'll fix that soon. So now we have our profiler report, oops, with the flame graph, which by the way is a vector graphic where you can zoom in and do fancy stuff with. So it's definitely worth taking a real look at it. And then it gives you a list of functions and back down here, more details. I will go into that very soon. Keep in mind, here is a link, show. So here's a alphabetically sorted list of functions and then all the functions that were analyzed in detail further down with their full call signature and whatnot. By default, the profiler will only document and find detailed and analyze the first, the top 10 functions by how much time was spent in themself, not in children, just in this function. Yeah, you can override that with command line options and say, I wanna see the top 100. HTML result will be a little bigger if you say all in a database that has 500,000 lines of code. So careful, yeah. What can be done is other things you can, instead of directly creating an HTML result, you can save the result into permanent tables and then bit by bit test how many functions do I really wanna document? Or you can export that data set and take it into your lab and look at it there because you don't wanna do the analysis of everything on your production machine. That's not what it's for, yeah? Anyhow, so now if I click on that show link, I get this. I get the full source code of my function and now I get, of course, since it's a very trivial function, it is not that sexy, but I see here that 96% of its time, the function spent in that one select. So I found exactly the problem query that I created. My colleague, Katie, she has the actual interactive design at our booth. If you stop by during the after hours or tomorrow, she can show you a hands-on real example of how this thing works, how the report really looks. It's interactive, yeah? And she used the actual Benchmark SQL database for that. Now, in addition, to fix this problem of paying the full overhead for the planning, parsing, and so on, instead of running a single command, you can give it a whole SQL file with all the stuff that you wanna execute, yeah? No matter how long it'll work. So that is one thing and on top of that, version three, edit the ability to profile an entire application. For that to work, the profiler needs to collect its data in shared memory. For that to work, it needs to be loaded via shared preload libraries, obviously. But once you have done that, you can control whether the profiler is collecting data or not with a command on the command line utility, the option monitor. It's very simple. It simply says, alter system set pure profiler active to true, and then says reload config. Yes, that's why this only works as of 9.4 or older. If you wanna use it on 9.3 or 9.2, you will have to edit the postgresql.conf file and hop the postmaster. Still, the profiler will work. But if you have performance problems and are on 9.2, don't profile, upgrade first, yeah? It's wasted time. Yeah, and then you again use the command line utility and can either save this, export it, or generate your reports. If you wanna play with the profiler really, really fast, quick, it is included in the big SQL binary installers. Just go to bigsql.org and go into the download sections and download the bigsql installer, get bigsql postgres, install the profiler, everything is built in there, yeah? If not, you can find it on Bitbucket, the whole thing and download it from there, but then you're living on the source tree, which is not as convenient. That was the keyword in the keynote, convenience. So that is the convenient and fast way. Bigsql has also integrated it into the bigsql manager, which is a graphical utility I know very little about. There it is, that much I know. And if you click on it, you get the nice GUI that asks you about your host name, DB user password and so on, nothing fancy there. And if you then click on generate, it puts the profile report right there into your webpage. You can click on the report itself and get it as a separate webpage by itself, download it, print it, send it via email. The whole report is completely self-contained. The SVG is inline. So you have one HTML file that you put as an attachment into an email and you tell, hey, we have a performance problem found and identified. And with that, I have just 10 minutes left for questions. Yes, you mean the dynamic SQL execute just the same way. So the time measurement is on that execute statement. Yeah, unfortunately it will not tell you what the final string that you assembled there looks like. That's a different thing. Yeah, that would be something that is definitely a room for improvement, but one execute statement could be executing any number of different SQL queries underneath if you have if else stuff that builds the query, then it's no help anyway. Yes, please. Only PLPG SQL and probably PLSQL, but I haven't tested that. Nothing. Nothing. The C function and all its queries will be part of that statement that invoked the C function. It's very simple. C functions do not execute callbacks. Neither do Python functions nor tickle functions for that matter. They don't invoke the callbacks that tell, hey, I'm entering a different function context now. So it can't do the accounting. Yep. We might want to think about that to at least give it context. Hey, I entered a different function. I don't know what's happening now, but I'm no longer responsible. That's somebody else's stuff. That might be an improvement, but that has to go into main Postgres. Definitely. Yes. Just on Postgres. No, not at this time. Yes, I will have to talk to Devrim about that. Definitely. I would like to get this thing since it's C only, well, C and Python. I would like to get it as a contrib module. Yeah, because it's really useful. But let's discuss that somewhere else. Yes, please. Yeah. Whatever PLPG SQL does there, it does. If you use a table that has partial indexes with parameters, will the Postgres query optimizer use your partial index? I don't think so. It shouldn't. Yeah? So yeah, that's one of the problems with queries inside of procedures. You have all this optimization done, and now you're using a partition table. And because your partition key is a parameter, the Postgres optimizer has no clue at that point when parsing and planning that query, what partitions it could exclude. So no constraint exclusion. Bye-bye feature. That's one of the bad things about PLPG SQL itself. Yes, please. Not yet, but yes, this is one thing that I'm thinking about how to design that. I don't want to overload the shared memory with all the possible explain outputs that can happen here. We need to figure out how and where we can save eventually plans, because the plan that's actually executed there might be something different from what happens when you cut and paste this out into P SQL and then look at it with some made-up parameters. Yeah? That's completely different. And it definitely is interesting to say, okay, for this query there, if you hit this statement, do an explain for me, please. Yeah? That would be one way to say, okay, I instrument this, I tell the profiler explicitly, you hit this function, that statement, give me an explain the first time you hit it. And you find that explain then in your Postmaster log or something like that. It's one thing, but I'm still thinking about how to do this in a really user-friendly way because running a profile and then telling this, this, this, this, this function I need to explain that it's not user-friendly, it's not convenient. So we need a different design there. Yes, please. If they use PLPG SQL, absolutely. Yes? Totally. All right? Thank you then.