We have moved our forum to GitHub Discussions. For questions about Phalcon v3/v4/v5 you can visit here and for Phalcon v6 here.

Logging queries from multiple connection services

Objective: Log all queries to a text file.

Problem: I have multiple database connection services and not all queries are being logged.

I have two database configurations

...
        $di->set('db', function () use ($di, $config) {

            $eventsManager = new EventManager();

            //Get a shared instance of the DbProfiler
            $profiler = $di->getProfiler();

            //Listen to all the database events
            $eventsManager->attach('db', function($event, $connection) use ($profiler) {
                if ($event->getType() == 'beforeQuery') {
                    $profiler->startProfile($connection->getSQLStatement());
                }
                if ($event->getType() == 'afterQuery') {
                    $profiler->stopProfile();
                }
            });

            $section = 'database_' . ENV;

            $connection = new DbAdapter(array(
                'host' => $config->{$section}->host,
                'username' => $config->{$section}->username,
                'password' => $config->{$section}->password,
                'dbname' => $config->{$section}->dbname
            ));

            $connection->setEventsManager($eventsManager);

            return $connection;
        });

        $di->set('db_old', function () use ($di, $config) {

            $eventsManager = new EventManager();

            //Get a shared instance of the DbProfiler
            $profiler = $di->getProfiler();

            //Listen to all the database events
            // $eventsManager->attach('db_old', function($event, $connection) use ($profiler) { // First attempt using "db_old"
            $eventsManager->attach('db', function($event, $connection) use ($profiler) {
                if ($event->getType() == 'beforeQuery') {
                    $profiler->startProfile($connection->getSQLStatement());
                }
                if ($event->getType() == 'afterQuery') {
                    $profiler->stopProfile();
                }
            });

            $section = 'database_' . ENV . '_old';

            $connection = new DbAdapter(array(
                'host' => $config->{$section}->host,
                'username' => $config->{$section}->username,
                'password' => $config->{$section}->password,
                'dbname' => $config->{$section}->dbname
            ));

            $connection->setEventsManager($eventsManager);

            return $connection;
        });
...

All of my controllers extend ControllerBase.php in which I have this:

... 
    public function afterExecuteRoute($dispatcher) {
      $config = $this->getDi()->get('config');
      $logs_dir = realpath($config->application->logsDir);
      $logger = new \Phalcon\Logger\Adapter\File($logs_dir . '/query_log.log');

      $profiles = $this->getDi()->get('profiler')->getProfiles();

      if ($profiles) {
          $total_query_time = 0;
          foreach ($profiles as $profile) {
          $total = (float) $profile->getTotalElapsedSeconds();

          $query_profile = array(
              'ts' => date("c"),
              'host' => gethostname(),
              'sql' => $profile->getSQLStatement(),
              'start' => $profile->getInitialTime(),
              'end' => $profile->getFinalTime(),
              'total' => $profile->getTotalElapsedSeconds()
          );

          $profile = json_encode($query_profile);
          $logger->log($profile, Logger::INFO);
          $total_query_time += (float) $total;
          }
          $logger->log(json_encode(array('TotalPageQueryTime' => $total)), Logger::INFO);
      }
    }
...

All of the queries from "db" are logged and I can log the first query from db_old, but any queries done in the view, for example:

                {% for taping in tapings.items %}
                    {% set settings = taping.getTapingStats() %}
                    {% set show = taping.getShows() %}
                    <tr {{ taping.getTapingActive() == '0' ? 'class="danger"' : '' }}>
                        <td>{{ taping.getTapingId() }}</td>
                        <td>{{ show.getShowTitle() }}</td>
                        <td>{{ taping.getTapingActive() == '0' ? 'No' : 'Yes' }}</td>
                        <td>{{ date("D, M d, Y @ g:i a", strtotime(taping.getTapingDate())) }}</td>
                        <td>{{ settings ? settings.getGroupsAllowed()|default('0') ? 'Yes' : 'No' : '-' }}</td>
                        <td>{{ settings ? settings.getGroupsNeeded()|default('-') : '-' }}</td>
                        <td>{{ settings ? settings.getGroupsNeeded() - taping.getGroupBookings().count() : '-' }}</td>
                        <td>{{ settings ? settings.getHasDonations() ? 'Yes' : 'No' : '-' }}</td>
                        <td>{{ settings ? settings.getHasTransportation() ? 'Yes' : 'No' : '-' }}</td>
                        <td class="text-center"><a href="{{ url({'for':'admin_tapings_view', 'show_id' : show.getShowId()}) }}">View</a></td>
                    </tr>

                {% endfor %}

The query for paginating the data in "tapings" is logged, all internal ACL queries are logged, but when I call "taping.getShows()" on each iteration, they are NOT logged but I do get results from them...

I've tried changing the eventManager settings from 'db' to 'db_old' but it only reduces the number of logged queries I get.

Eventually, these logs will be used in the ELK stack to monitor real-time query performance so making sure I can log all queries is a must.



5.7k

I was able to get a little more info after some digging into the issue.

The initial query from the "Tapings" model, which uses db_old, IS logging correctly. However, the calls to the related Model Shows is not logged.

This line is executed and provides a valid result, but not logged.

                    {% set show = taping.getShows() %}


5.7k

Thanks for the reply.

I thought about logging directly in the connection services (db and db_old in my case) but I didn't want it to open the log file before writing each query or each call to the service. It seems like that would cause a lot of unnecessary overhead opening the log file over and over again.

The goal was to use the profiler to capture all of the queries and their execution times, then once afterExecuteRoute() was called, log all those queries with a single call to \Phalcon\Logger\Adapter\File (from within ControllerBase.php, which each controller extends) so that the log file is only opened once, written to in a loop, then closed once.