CDR/CEL Custom Performance Improvements

There is a LOT of work in this commit but the TL;DR is that it takes
CEL processing from using 38% of the CPU instructions used by a call,
which is more than that used by the call processing itself, down to less
than 10% of the instructions.

So here's the deal...  cdr_custom, cdr_sqlite3_custom, cel_custom
and cel_sqlite3_custom all shared one ugly trait...they all used
ast_str_substitute_variables() or pbx_substitute_variables_helper()
to resolve the dialplan functions used in their config files.  Not only
are they both extraordinarily expensive, they both require a dummy
channel to be allocated and destroyed for each record written.  For CDRs,
that's not too bad because we only write one CDR per call.  For CELs however,
it's a disaster.

As far as source code goes, the modules basically all did the same thing.
Unfortunately, they did it badly.  The config files simply contained long
opaque strings which were intepreted by ast_str_substitute_variables() or
pbx_substitute_variables_helper(), the very functions that ate all the
instructions.  This meant introducing a new "advanced" config format much
like the advanced manager event filtering added to manager.conf in 2024.
Fortunately however, if the legacy config was recognizable, we were able to
parse it as an advanced config and gain the benefit.  If not, then it
goes the legacy, and very expensive, route.

Given the commonality among the modules, instead of making the same
improvements to 4 modules then trying to maintain them over time, a single
module "res_cdrel_custom" was created that contains all of the common code.
A few bonuses became possible in the process...
* The cdr_custom and cel_custom modules now support JSON formatted output.
* The cdr_sqlite_custom and cel_sqlite3_custom modules no longer have
  to share an Sqlite3 database.

Summary of changes:

A new module "res/res_cdrel_custom.c" has been created and the existing
cdr_custom, cdr_sqlite3_custom, cel_custom and cel_sqlite3_custom modules
are now just stubs that call the code in res_cdrel_custom.

res_cdrel_custom contains:
* A common configuration facility.
* Getters for both CDR and CEL fields that share the same abstraction.
* Formatters for all data types found in the ast_cdr and ast_event
  structures that share the same abstraction.
* Common writers for the text file and database backends that, you guessed it,
  share the same abstraction.

The result is that while there is certainly a net increase in the number of
lines in the code base, most of it is in the configuration handling at
load-time.  The run-time instruction path length is now significanty shorter.

```
Scenario                   Instructions     Latency
=====================================================
CEL pre changes                  38.49%     37.51%
CEL Advanced                      9.68%      6.06%
CEL Legacy (auto-conv to adv)     9.95%      6.13%

CEL Sqlite3 pre changes          39.41%     39.90%
CEL Sqlite3 Advanced             25.68%     24.24%
CEL Sqlite3 Legacy (auto conv)   25.88%     24.53%

CDR pre changes                   4.79%      2.95%
CDR Advanced                      0.79%      0.47%
CDR Legacy (auto conv to adv)     0.86%      0.51%

CDR Sqlite3 pre changes           4.47%      2.89%
CEL Sqlite3 Advanced              2.16%      1.29%
CEL Sqlite3 Legacy (auto conv)    2.19%      1.30%
```

Notes:
* We only write one CDR per call but every little bit helps.
* Sqlite3 still takes a fair amount of resources but the new config
  makes a decent improvement.
* Legacy configs that we can't auto convert will still take the
  "pre changes" path.

If you're interested in more implementation details, see the comments
at the top of the res_cdrel_custom.c file.

One minor fix to CEL is also included...Although TenantID was added to the
ast_event structure, it was always rendered as an empty string.  It's now
properly rendered.

UserNote: Significant performance improvements have been made to the
cdr_custom, cdr_sqlite3_custom, cel_custom and cel_sqlite3_custom modules.
See the new sample config files for those modules to see how to benefit
from them.
This commit is contained in:
George Joseph
2026-01-27 12:57:21 -07:00
parent 5f19f10d26
commit 23fa44d2eb
22 changed files with 4036 additions and 921 deletions
+32 -280
View File
@@ -27,9 +27,13 @@
* cdr_mysql_custom by Edward Eastman <ed@dm3.co.uk>,
* and cdr_sqlite by Holger Schurig <hs4233@mail.mn-solutions.de>
* \ingroup cel_drivers
*
* The logic for this module now resides in res/res_cdrel_custom.c.
*
*/
/*** MODULEINFO
<depend>res_cdrel_custom</depend>
<depend>sqlite3</depend>
<support_level>extended</support_level>
***/
@@ -38,314 +42,62 @@
#include <sqlite3.h>
#include "asterisk/paths.h"
#include "asterisk/channel.h"
#include "asterisk/cel.h"
#include "asterisk/module.h"
#include "asterisk/config.h"
#include "asterisk/pbx.h"
#include "asterisk/logger.h"
#include "asterisk/utils.h"
#include "asterisk/cli.h"
#include "asterisk/options.h"
#include "asterisk/stringfields.h"
#include "asterisk/res_cdrel_custom.h"
#define SQLITE_BACKEND_NAME "CEL sqlite3 custom backend"
#define CONFIG "cel_sqlite3_custom.conf"
AST_MUTEX_DEFINE_STATIC(lock);
#define CUSTOM_BACKEND_NAME "CEL sqlite3 custom backend"
static const char config_file[] = "cel_sqlite3_custom.conf";
static struct cdrel_configs *configs;
static sqlite3 *db = NULL;
static char table[80];
/*!
* \bug Handling of this var is crash prone on reloads
* Protects in-flight log transactions from reloads.
*/
static char *columns;
static int busy_timeout;
static ast_rwlock_t configs_lock;
struct values {
char *expression;
AST_LIST_ENTRY(values) list;
};
#define CDREL_RECORD_TYPE cdrel_record_cel
#define CDREL_BACKEND_TYPE cdrel_backend_db
static AST_LIST_HEAD_STATIC(sql_values, values);
static void free_config(void);
static int load_column_config(const char *tmp)
static void custom_log(struct ast_event *event)
{
char *col = NULL;
char *cols = NULL, *save = NULL;
char *escaped = NULL;
struct ast_str *column_string = NULL;
if (ast_strlen_zero(tmp)) {
ast_log(LOG_WARNING, "Column names not specified. Module not loaded.\n");
return -1;
}
if (!(column_string = ast_str_create(1024))) {
ast_log(LOG_ERROR, "Out of memory creating temporary buffer for column list for table '%s.'\n", table);
return -1;
}
if (!(save = cols = ast_strdup(tmp))) {
ast_log(LOG_ERROR, "Out of memory creating temporary buffer for column list for table '%s.'\n", table);
ast_free(column_string);
return -1;
}
while ((col = strsep(&cols, ","))) {
col = ast_strip(col);
escaped = sqlite3_mprintf("%q", col);
if (!escaped) {
ast_log(LOG_ERROR, "Out of memory creating entry for column '%s' in table '%s.'\n", col, table);
ast_free(column_string);
ast_free(save);
return -1;
}
ast_str_append(&column_string, 0, "%s%s", ast_str_strlen(column_string) ? "," : "", escaped);
sqlite3_free(escaped);
}
if (!(columns = ast_strdup(ast_str_buffer(column_string)))) {
ast_log(LOG_ERROR, "Out of memory copying columns string for table '%s.'\n", table);
ast_free(column_string);
ast_free(save);
return -1;
}
ast_free(column_string);
ast_free(save);
return 0;
}
static int load_values_config(const char *tmp)
{
char *val = NULL;
char *vals = NULL, *save = NULL;
struct values *value = NULL;
if (ast_strlen_zero(tmp)) {
ast_log(LOG_WARNING, "Values not specified. Module not loaded.\n");
return -1;
}
if (!(save = vals = ast_strdup(tmp))) {
ast_log(LOG_ERROR, "Out of memory creating temporary buffer for value '%s'\n", tmp);
return -1;
}
while ((val = strsep(&vals, ","))) {
/* Strip the single quotes off if they are there */
val = ast_strip_quoted(val, "'", "'");
value = ast_calloc(sizeof(char), sizeof(*value) + strlen(val) + 1);
if (!value) {
ast_log(LOG_ERROR, "Out of memory creating entry for value '%s'\n", val);
ast_free(save);
return -1;
}
value->expression = (char *) value + sizeof(*value);
ast_copy_string(value->expression, val, strlen(val) + 1);
AST_LIST_INSERT_TAIL(&sql_values, value, list);
}
ast_free(save);
return 0;
}
static int load_config(int reload)
{
struct ast_config *cfg;
struct ast_flags config_flags = { reload ? CONFIG_FLAG_FILEUNCHANGED : 0 };
struct ast_variable *mappingvar;
const char *tmp;
if ((cfg = ast_config_load(config_file, config_flags)) == CONFIG_STATUS_FILEMISSING || cfg == CONFIG_STATUS_FILEINVALID) {
ast_log(LOG_WARNING, "Failed to %sload configuration file. %s\n",
reload ? "re" : "", reload ? "" : "Module not activated.");
return -1;
} else if (cfg == CONFIG_STATUS_FILEUNCHANGED) {
return 0;
}
if (reload) {
free_config();
}
if (!(mappingvar = ast_variable_browse(cfg, "master"))) {
/* Nothing configured */
ast_config_destroy(cfg);
return -1;
}
/* Mapping must have a table name */
if (!ast_strlen_zero(tmp = ast_variable_retrieve(cfg, "master", "table"))) {
ast_copy_string(table, tmp, sizeof(table));
} else {
ast_log(LOG_WARNING, "Table name not specified. Assuming cel.\n");
strcpy(table, "cel");
}
/* sqlite3_busy_timeout in miliseconds */
if ((tmp = ast_variable_retrieve(cfg, "master", "busy_timeout")) != NULL) {
if (ast_parse_arg(tmp, PARSE_INT32|PARSE_DEFAULT, &busy_timeout, 1000) != 0) {
ast_log(LOG_WARNING, "Invalid busy_timeout value '%s' specified. Using 1000 instead.\n", tmp);
}
} else {
busy_timeout = 1000;
}
/* Columns */
if (load_column_config(ast_variable_retrieve(cfg, "master", "columns"))) {
ast_config_destroy(cfg);
free_config();
return -1;
}
/* Values */
if (load_values_config(ast_variable_retrieve(cfg, "master", "values"))) {
ast_config_destroy(cfg);
free_config();
return -1;
}
ast_verb(3, "Logging CEL records to table '%s' in 'master.db'\n", table);
ast_config_destroy(cfg);
return 0;
}
static void free_config(void)
{
struct values *value;
if (db) {
sqlite3_close(db);
db = NULL;
}
if (columns) {
ast_free(columns);
columns = NULL;
}
while ((value = AST_LIST_REMOVE_HEAD(&sql_values, list))) {
ast_free(value);
}
}
static void write_cel(struct ast_event *event)
{
char *error = NULL;
char *sql = NULL;
if (db == NULL) {
/* Should not have loaded, but be failsafe. */
return;
}
ast_mutex_lock(&lock);
{ /* Make it obvious that only sql should be used outside of this block */
char *escaped;
char subst_buf[2048];
struct values *value;
struct ast_channel *dummy;
struct ast_str *value_string = ast_str_create(1024);
dummy = ast_cel_fabricate_channel_from_event(event);
if (!dummy) {
ast_log(LOG_ERROR, "Unable to fabricate channel from CEL event.\n");
ast_free(value_string);
ast_mutex_unlock(&lock);
return;
}
AST_LIST_TRAVERSE(&sql_values, value, list) {
pbx_substitute_variables_helper(dummy, value->expression, subst_buf, sizeof(subst_buf) - 1);
escaped = sqlite3_mprintf("%q", subst_buf);
ast_str_append(&value_string, 0, "%s'%s'", ast_str_strlen(value_string) ? "," : "", escaped);
sqlite3_free(escaped);
}
sql = sqlite3_mprintf("INSERT INTO %q (%s) VALUES (%s)", table, columns, ast_str_buffer(value_string));
ast_debug(1, "About to log: %s\n", sql);
dummy = ast_channel_unref(dummy);
ast_free(value_string);
}
if (sqlite3_exec(db, sql, NULL, NULL, &error) != SQLITE_OK) {
ast_log(LOG_ERROR, "%s. SQL: %s.\n", error, sql);
sqlite3_free(error);
}
if (sql) {
sqlite3_free(sql);
}
ast_mutex_unlock(&lock);
return;
ast_rwlock_rdlock(&configs_lock);
cdrel_logger(configs, event);
ast_rwlock_unlock(&configs_lock);
}
static int unload_module(void)
{
ast_cel_backend_unregister(SQLITE_BACKEND_NAME);
int res = 0;
free_config();
ast_rwlock_wrlock(&configs_lock);
res = cdrel_unload_module(CDREL_BACKEND_TYPE, CDREL_RECORD_TYPE, configs, CUSTOM_BACKEND_NAME);
ast_rwlock_unlock(&configs_lock);
if (res == 0) {
ast_rwlock_destroy(&configs_lock);
}
return 0;
return res;
}
static int load_module(void)
static enum ast_module_load_result load_module(void)
{
char *error;
char filename[PATH_MAX];
int res;
char *sql;
if (load_config(0)) {
if (ast_rwlock_init(&configs_lock) != 0) {
return AST_MODULE_LOAD_DECLINE;
}
/* is the database there? */
snprintf(filename, sizeof(filename), "%s/master.db", ast_config_AST_LOG_DIR);
res = sqlite3_open(filename, &db);
if (res != SQLITE_OK) {
ast_log(LOG_ERROR, "Could not open database %s.\n", filename);
free_config();
return AST_MODULE_LOAD_DECLINE;
}
sqlite3_busy_timeout(db, busy_timeout);
/* is the table there? */
sql = sqlite3_mprintf("SELECT COUNT(*) FROM %q;", table);
res = sqlite3_exec(db, sql, NULL, NULL, NULL);
sqlite3_free(sql);
if (res != SQLITE_OK) {
/* We don't use %q for the column list here since we already escaped when building it */
sql = sqlite3_mprintf("CREATE TABLE %q (AcctId INTEGER PRIMARY KEY, %s)", table, columns);
res = sqlite3_exec(db, sql, NULL, NULL, &error);
sqlite3_free(sql);
if (res != SQLITE_OK) {
ast_log(LOG_WARNING, "Unable to create table '%s': %s.\n", table, error);
sqlite3_free(error);
free_config();
return AST_MODULE_LOAD_DECLINE;
}
}
configs = cdrel_load_module(CDREL_BACKEND_TYPE, CDREL_RECORD_TYPE, CONFIG, CUSTOM_BACKEND_NAME, custom_log);
if (ast_cel_backend_register(SQLITE_BACKEND_NAME, write_cel)) {
ast_log(LOG_ERROR, "Unable to register custom SQLite3 CEL handling\n");
free_config();
return AST_MODULE_LOAD_DECLINE;
}
return AST_MODULE_LOAD_SUCCESS;
return configs ? AST_MODULE_LOAD_SUCCESS : AST_MODULE_LOAD_DECLINE;
}
static int reload(void)
{
int res = 0;
ast_mutex_lock(&lock);
res = load_config(1);
ast_mutex_unlock(&lock);
ast_rwlock_wrlock(&configs_lock);
res = cdrel_reload_module(CDREL_BACKEND_TYPE, CDREL_RECORD_TYPE, &configs, CONFIG);
ast_rwlock_unlock(&configs_lock);
return res;
}
@@ -355,5 +107,5 @@ AST_MODULE_INFO(ASTERISK_GPL_KEY, AST_MODFLAG_LOAD_ORDER, "SQLite3 Custom CEL Mo
.unload = unload_module,
.reload = reload,
.load_pri = AST_MODPRI_CDR_DRIVER,
.requires = "cel",
.requires = "cel,res_cdrel_custom",
);