You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

473 lines
18 KiB

  1. import base64
  2. import logging
  3. import os
  4. import pstats
  5. import re
  6. import subprocess
  7. import lxml.html
  8. from contextlib import contextmanager
  9. from cProfile import Profile
  10. from io import StringIO
  11. from psycopg2 import OperationalError, ProgrammingError
  12. from odoo import api, exceptions, fields, models, sql_db, tools, _
  13. DATETIME_FORMAT_FILE = "%Y%m%d_%H%M%S"
  14. CPROFILE_EMPTY_CHARS = b"{0"
  15. PGOPTIONS = {
  16. 'log_min_duration_statement': '0',
  17. 'client_min_messages': 'notice',
  18. 'log_min_messages': 'warning',
  19. 'log_min_error_statement': 'error',
  20. 'log_duration': 'off',
  21. 'log_error_verbosity': 'verbose',
  22. 'log_lock_waits': 'on',
  23. 'log_statement': 'none',
  24. 'log_temp_files': '0',
  25. }
  26. PGOPTIONS_ENV = ' '.join(["-c %s=%s" % (param, value)
  27. for param, value in PGOPTIONS.items()])
  28. PY_STATS_FIELDS = [
  29. 'ncalls',
  30. 'tottime', 'tt_percall',
  31. 'cumtime', 'ct_percall',
  32. 'file', 'lineno', 'method',
  33. ]
  34. LINE_STATS_RE = re.compile(
  35. r'(?P<%s>\d+/?\d+|\d+)\s+(?P<%s>\d+\.?\d+)\s+(?P<%s>\d+\.?\d+)\s+'
  36. r'(?P<%s>\d+\.?\d+)\s+(?P<%s>\d+\.?\d+)\s+(?P<%s>.*):(?P<%s>\d+)'
  37. r'\((?P<%s>.*)\)' % tuple(PY_STATS_FIELDS))
  38. _logger = logging.getLogger(__name__)
  39. class ProfilerProfilePythonLine(models.Model):
  40. _name = 'profiler.profile.python.line'
  41. _description = 'Profiler Python Line to save cProfiling results'
  42. _rec_name = 'cprof_fname'
  43. _order = 'cprof_cumtime DESC'
  44. profile_id = fields.Many2one('profiler.profile', required=True,
  45. ondelete='cascade')
  46. cprof_tottime = fields.Float("Total time")
  47. cprof_ncalls = fields.Float("Calls")
  48. cprof_nrcalls = fields.Float("Recursive Calls")
  49. cprof_ttpercall = fields.Float("Time per call")
  50. cprof_cumtime = fields.Float("Cumulative time")
  51. cprof_ctpercall = fields.Float("CT per call")
  52. cprof_fname = fields.Char("Filename:lineno(method)")
  53. class ProfilerProfile(models.Model):
  54. _name = 'profiler.profile'
  55. _description = 'Profiler Profile'
  56. @api.model
  57. def _find_loggers_path(self):
  58. self.env.cr.execute("SHOW log_directory")
  59. log_directory = self.env.cr.fetchone()[0]
  60. self.env.cr.execute("SHOW log_filename")
  61. log_filename = self.env.cr.fetchone()[0]
  62. log_path = os.path.join(log_directory, log_filename)
  63. if not os.path.isabs(log_path):
  64. # It is relative path then join data_directory
  65. self.env.cr.execute("SHOW data_directory")
  66. data_dir = self.env.cr.fetchone()[0]
  67. log_path = os.path.join(data_dir, log_path)
  68. return log_path
  69. name = fields.Char(required=True)
  70. enable_python = fields.Boolean(default=True)
  71. enable_postgresql = fields.Boolean(
  72. default=False,
  73. help="It requires postgresql server logs seudo-enabled")
  74. use_py_index = fields.Boolean(
  75. name="Get cProfiling report", default=False,
  76. help="Index human-readable cProfile attachment."
  77. "\nTo access this report, you must open the cprofile attachment view "
  78. "using debug mode.\nWarning: Uses more resources.")
  79. date_started = fields.Char(readonly=True)
  80. date_finished = fields.Char(readonly=True)
  81. state = fields.Selection([
  82. ('enabled', 'Enabled'),
  83. ('disabled', 'Disabled'),
  84. ], default='disabled', readonly=True, required=True)
  85. description = fields.Text(readonly=True)
  86. attachment_count = fields.Integer(compute="_compute_attachment_count")
  87. pg_log_path = fields.Char(help="Getting the path to the logger",
  88. default=_find_loggers_path)
  89. pg_remote = fields.Char()
  90. pg_stats_slowest_html = fields.Html(
  91. "PostgreSQL Stats - Slowest", readonly=True)
  92. pg_stats_time_consuming_html = fields.Html(
  93. "PostgreSQL Stats - Time Consuming", readonly=True)
  94. pg_stats_most_frequent_html = fields.Html(
  95. "PostgreSQL Stats - Most Frequent", readonly=True)
  96. py_stats_lines = fields.One2many(
  97. "profiler.profile.python.line", "profile_id", "PY Stats Lines")
  98. @api.multi
  99. def _compute_attachment_count(self):
  100. for record in self:
  101. self.attachment_count = self.env['ir.attachment'].search_count([
  102. ('res_model', '=', self._name), ('res_id', '=', record.id)])
  103. @api.onchange('enable_postgresql')
  104. def onchange_enable_postgresql(self):
  105. if not self.enable_postgresql:
  106. return
  107. self.env.cr.execute("SHOW config_file")
  108. pg_config_file = self.env.cr.fetchone()[0]
  109. db_host = tools.config.get('db_host')
  110. if db_host == 'localhost' or db_host == '127.0.0.1':
  111. db_host = False
  112. if db_host:
  113. pg_config_file = 'postgres@%s:%s' % (db_host, pg_config_file)
  114. self.pg_remote = db_host
  115. self.description = (
  116. "You need seudo-enable logs from your "
  117. "postgresql-server configuration file.\n"
  118. "Common paths:\n\t- %s\n"
  119. "or your can looking for the service using: "
  120. "'ps aux | grep postgres'\n\n"
  121. ) % pg_config_file
  122. self.description += """Adds the following parameters:
  123. # Pre-enable logs
  124. logging_collector=on
  125. log_destination='stderr'
  126. log_directory='/var/log/postgresql'
  127. log_filename='postgresql.log'
  128. log_rotation_age=0
  129. log_checkpoints=on
  130. log_hostname=on
  131. log_line_prefix='%t [%p]: [%l-1] db=%d,user=%u '
  132. log_connections=on
  133. log_disconnections=on
  134. lc_messages='en_US.UTF-8'
  135. log_timezone='UTC'
  136. Reload configuration using the following query:
  137. - select pg_reload_conf()
  138. Or restart the postgresql server service.
  139. FYI This module will enable the following parameter from the client
  140. It's not needed added them to configuration file if database user is
  141. superuser or use PGOPTIONS environment variable in the terminal
  142. that you start your odoo server.
  143. If you don't add these parameters or PGOPTIONS this module will try do it.
  144. # Enable logs from postgresql.conf
  145. log_min_duration_statement=0
  146. client_min_messages=notice
  147. log_min_messages=warning
  148. log_min_error_statement=error
  149. log_duration=off
  150. log_error_verbosity=verbose
  151. log_lock_waits=on
  152. log_statement=none
  153. log_temp_files=0
  154. # Or enable logs from PGOPTIONS environment variable before to start odoo
  155. # server
  156. export PGOPTIONS="-c log_min_duration_statement=0 \\
  157. -c client_min_messages=notice -c log_min_messages=warning \\
  158. -c log_min_error_statement=error -c log_connections=on \\
  159. -c log_disconnections=on -c log_duration=off -c log_error_verbosity=verbose \\
  160. -c log_lock_waits=on -c log_statement=none -c log_temp_files=0"
  161. ~/odoo_path/odoo-bin ...
  162. """
  163. profile = Profile()
  164. enabled = None
  165. pglogs_enabled = None
  166. # True to activate it False to inactivate None to do nothing
  167. activate_deactivate_pglogs = None
  168. # Params dict with values before to change it.
  169. psql_params_original = {}
  170. @api.model
  171. def now_utc(self):
  172. self.env.cr.execute("SHOW log_timezone")
  173. zone = self.env.cr.fetchone()[0]
  174. self.env.cr.execute("SELECT to_char(current_timestamp AT TIME "
  175. "ZONE %s, 'YYYY-MM-DD HH24:MI:SS')", (zone,))
  176. now = self.env.cr.fetchall()[0][0]
  177. # now = fields.Datetime.to_string(
  178. # fields.Datetime.context_timestamp(self, datetime.now()))
  179. return now
  180. @api.multi
  181. def enable(self):
  182. self.ensure_one()
  183. if tools.config.get('workers'):
  184. raise exceptions.UserError(
  185. _("Start the odoo server using the parameter '--workers=0'"))
  186. _logger.info("Enabling profiler")
  187. self.write(dict(
  188. date_started=self.now_utc(),
  189. state='enabled'
  190. ))
  191. ProfilerProfile.enabled = self.enable_python
  192. self._reset_postgresql()
  193. @api.multi
  194. def _reset_postgresql(self):
  195. if not self.enable_postgresql:
  196. return
  197. if ProfilerProfile.pglogs_enabled:
  198. _logger.info("Using postgresql.conf or PGOPTIONS predefined.")
  199. return
  200. os.environ['PGOPTIONS'] = (
  201. PGOPTIONS_ENV if self.state == 'enabled' else '')
  202. self._reset_connection(self.state == 'enabled')
  203. def _reset_connection(self, enable):
  204. for connection in sql_db._Pool._connections:
  205. with connection[0].cursor() as pool_cr:
  206. params = (PGOPTIONS if enable
  207. else ProfilerProfile.psql_params_original)
  208. for param, value in params.items():
  209. try:
  210. pool_cr.execute('SET %s TO %s' % (param, value))
  211. except (OperationalError, ProgrammingError) as oe:
  212. pool_cr.connection.rollback()
  213. raise exceptions.UserError(
  214. _("It's not possible change parameter.\n%s\n"
  215. "Please, disable postgresql or re-enable it "
  216. "in order to read the instructions") % str(oe))
  217. ProfilerProfile.activate_deactivate_pglogs = enable
  218. def get_stats_string(self, cprofile_path):
  219. pstats_stream = StringIO()
  220. pstats_obj = pstats.Stats(cprofile_path, stream=pstats_stream)
  221. pstats_obj.sort_stats('cumulative')
  222. pstats_obj.print_stats()
  223. pstats_stream.seek(0)
  224. stats_string = pstats_stream.read()
  225. pstats_stream = None
  226. return stats_string
  227. @api.multi
  228. def dump_postgresql_logs(self, indexed=None):
  229. self.ensure_one()
  230. self.description = ''
  231. pgbadger_cmd = self._get_pgbadger_command()
  232. if pgbadger_cmd is None:
  233. return
  234. pgbadger_cmd_str = subprocess.list2cmdline(pgbadger_cmd)
  235. self.description += (
  236. '\nRunning the command: %s') % pgbadger_cmd_str
  237. result = tools.exec_command_pipe(*pgbadger_cmd)
  238. datas = result[1].read()
  239. if not datas:
  240. self.description += "\nPgbadger output is empty!"
  241. return
  242. fname = self._get_attachment_name("pg_stats", ".html")
  243. self.env['ir.attachment'].create({
  244. 'name': fname,
  245. 'res_id': self.id,
  246. 'res_model': self._name,
  247. 'datas': base64.b64encode(datas),
  248. 'datas_fname': fname,
  249. 'description': 'pgbadger html output',
  250. })
  251. xpaths = [
  252. '//*[@id="slowest-individual-queries"]',
  253. '//*[@id="time-consuming-queries"]',
  254. '//*[@id="most-frequent-queries"]',
  255. ]
  256. # pylint: disable=unbalanced-tuple-unpacking
  257. self.pg_stats_slowest_html, self.pg_stats_time_consuming_html, \
  258. self.pg_stats_most_frequent_html = self._compute_pgbadger_html(
  259. datas, xpaths)
  260. @staticmethod
  261. def _compute_pgbadger_html(html_doc, xpaths):
  262. html = lxml.html.document_fromstring(html_doc)
  263. result = []
  264. for this_xpath in xpaths:
  265. this_result = html.xpath(this_xpath)
  266. result.append(
  267. tools.html_sanitize(lxml.html.tostring(this_result[0])))
  268. return result
  269. @api.multi
  270. def _get_pgbadger_command(self):
  271. self.ensure_one()
  272. # TODO: Catch early the following errors.
  273. try:
  274. pgbadger_bin = tools.find_in_path('pgbadger')
  275. except IOError:
  276. self.description += (
  277. "\nInstall 'apt-get install pgbadger'")
  278. try:
  279. with open(self.pg_log_path, "r"):
  280. pass
  281. except IOError:
  282. self.description += (
  283. "\nCheck if exists and has permission to read the log file."
  284. "\nMaybe running: chmod 604 '%s'"
  285. ) % self.pg_log_path
  286. pgbadger_cmd = [
  287. pgbadger_bin, '-f', 'stderr', '--sample', '15',
  288. '-o', '-', '-x', 'html', '--quiet',
  289. '-T', self.name,
  290. '-d', self.env.cr.dbname,
  291. '-b', self.date_started,
  292. '-e', self.date_finished,
  293. self.pg_log_path,
  294. ]
  295. return pgbadger_cmd
  296. def _get_attachment_name(self, prefix, suffix):
  297. started = fields.Datetime.from_string(
  298. self.date_started).strftime(DATETIME_FORMAT_FILE)
  299. finished = fields.Datetime.from_string(
  300. self.date_finished).strftime(DATETIME_FORMAT_FILE)
  301. fname = '%s_%d_%s_to_%s%s' % (
  302. prefix, self.id, started, finished, suffix)
  303. return fname
  304. @api.model
  305. def dump_stats(self):
  306. attachment = None
  307. with tools.osutil.tempdir() as dump_dir:
  308. cprofile_fname = self._get_attachment_name("py_stats", ".cprofile")
  309. cprofile_path = os.path.join(dump_dir, cprofile_fname)
  310. _logger.info("Dumping cProfile '%s'", cprofile_path)
  311. ProfilerProfile.profile.dump_stats(cprofile_path)
  312. with open(cprofile_path, "rb") as f_cprofile:
  313. datas = f_cprofile.read()
  314. if datas and datas != CPROFILE_EMPTY_CHARS:
  315. attachment = self.env['ir.attachment'].create({
  316. 'name': cprofile_fname,
  317. 'res_id': self.id,
  318. 'res_model': self._name,
  319. 'datas': base64.b64encode(datas),
  320. 'datas_fname': cprofile_fname,
  321. 'description': 'cProfile dump stats',
  322. })
  323. _logger.info("A datas was saved, here %s", attachment.name)
  324. try:
  325. if self.use_py_index:
  326. py_stats = self.get_stats_string(cprofile_path)
  327. self.env['profiler.profile.python.line'].search([
  328. ('profile_id', '=', self.id)]).unlink()
  329. for py_stat_line in py_stats.splitlines():
  330. py_stat_line = py_stat_line.strip('\r\n ')
  331. py_stat_line_match = LINE_STATS_RE.match(
  332. py_stat_line) if py_stat_line else None
  333. if not py_stat_line_match:
  334. continue
  335. data = dict((
  336. field, py_stat_line_match.group(field))
  337. for field in PY_STATS_FIELDS)
  338. data['rcalls'], data['calls'] = (
  339. "%(ncalls)s/%(ncalls)s" % data).split('/')[:2]
  340. self.env['profiler.profile.python.line'].create({
  341. 'cprof_tottime': data['tottime'],
  342. 'cprof_ncalls': data['calls'],
  343. 'cprof_nrcalls': data['rcalls'],
  344. 'cprof_ttpercall': data['tt_percall'],
  345. 'cprof_cumtime': data['cumtime'],
  346. 'cprof_ctpercall': data['ct_percall'],
  347. 'cprof_fname': (
  348. "%(file)s:%(lineno)s (%(method)s)" % data),
  349. 'profile_id': self.id,
  350. })
  351. attachment.index_content = py_stats
  352. except IOError:
  353. # Fancy feature but not stop process if fails
  354. _logger.info("There was an error while getting the stats"
  355. "from the cprofile_path")
  356. # pylint: disable=unnecessary-pass
  357. pass
  358. self.dump_postgresql_logs()
  359. _logger.info("cProfile stats stored.")
  360. else:
  361. _logger.info("cProfile stats empty.")
  362. return attachment
  363. @api.multi
  364. def clear(self, reset_date=True):
  365. self.ensure_one()
  366. _logger.info("Clear profiler")
  367. if reset_date:
  368. self.date_started = self.now_utc()
  369. ProfilerProfile.profile.clear()
  370. @api.multi
  371. def disable(self):
  372. self.ensure_one()
  373. _logger.info("Disabling profiler")
  374. ProfilerProfile.enabled = False
  375. self.state = 'disabled'
  376. self.date_finished = self.now_utc()
  377. self.dump_stats()
  378. self.clear(reset_date=False)
  379. self._reset_postgresql()
  380. @staticmethod
  381. @contextmanager
  382. def profiling():
  383. """Thread local profile management, according to the shared "enabled"
  384. """
  385. if ProfilerProfile.enabled:
  386. _logger.debug("Catching profiling")
  387. ProfilerProfile.profile.enable()
  388. try:
  389. yield
  390. finally:
  391. if ProfilerProfile.enabled:
  392. ProfilerProfile.profile.disable()
  393. @api.multi
  394. def action_view_attachment(self):
  395. attachments = self.env['ir.attachment'].search([
  396. ('res_model', '=', self._name), ('res_id', '=', self.id)])
  397. action = self.env.ref("base.action_attachment").read()[0]
  398. action['domain'] = [('id', 'in', attachments.ids)]
  399. return action
  400. @api.model
  401. def set_pgoptions_enabled(self):
  402. """Verify if postgresql has configured the parameters for logging"""
  403. ProfilerProfile.pglogs_enabled = True
  404. pgoptions_enabled = bool(os.environ.get('PGOPTIONS'))
  405. _logger.info('Logging enabled from environment '
  406. 'variable PGOPTIONS? %s', pgoptions_enabled)
  407. if pgoptions_enabled:
  408. return
  409. pgparams_required = {
  410. 'log_min_duration_statement': '0',
  411. }
  412. for param, value in pgparams_required.items():
  413. # pylint: disable=sql-injection
  414. self.env.cr.execute("SHOW %s" % param)
  415. db_value = self.env.cr.fetchone()[0].lower()
  416. if value.lower() != db_value:
  417. ProfilerProfile.pglogs_enabled = False
  418. break
  419. ProfilerProfile.psql_params_original = self.get_psql_params(
  420. self.env.cr, PGOPTIONS.keys())
  421. _logger.info('Logging enabled from postgresql.conf? %s',
  422. ProfilerProfile.pglogs_enabled)
  423. @staticmethod
  424. def get_psql_params(cr, params):
  425. result = {}
  426. for param in set(params):
  427. # pylint: disable=sql-injection
  428. cr.execute('SHOW %s' % param)
  429. result.update(cr.dictfetchone())
  430. return result
  431. @api.model
  432. def _setup_complete(self):
  433. self.set_pgoptions_enabled()
  434. return super(ProfilerProfile, self)._setup_complete()