It helps to debug queries executed in postgresql from Odoo
in order to know where they were called
Enabling the postgresql logs with the following `log_line_prefix`
log_line_prefix='%t [%p]: [%l-1] db=%d,user=%u,client=%h,app=%a '
You will see the following output in the postgresql.log:
... UTC [394452]: [371-1] db=odoo,user=odoo,client=127.0.0.1,app=odoo-740755 LOG: 00000: duration: 0.074 ms statement: SELECT 1
Notice `app=odoo-740755` it is the odoo pid that executed the query
and the postgresql PID `... UTC [394452]:`
Then you will be able to match the odoo.log and postgresql.log using the PIDs
740755 DEBUG odoo odoo.sql_db.connection: ConnectionPool(used=1/count=2/max=64) Create new connection backend PID 394452
740755 INFO odoo odoo.addons: Running SELECT 1
Notice the Odoo PID `740755 INFO` and the postgresql PID `backend pid 394452`
Note: It will require enable the sub-logger
- `--log-handler=odoo.sql_db.connection:DEBUG`
It will helps to debug what process is executing each query in the database
or if a postgressql PID is showing a error log related to connection (not even from a query)
e.g. The livechat stuck and you don't know what happen but you can see the postgresql.log the following message
for the same PostgreSQL backend_pid related to longpolling odoo pid
[394452]: [371-2] db=odoo,user=odoo,client=127.0.0.1,app=odoo-740755 LOG: XX00: Could not receive data from client: Connection time out
closesodoo/odoo#82857
Signed-off-by: Xavier Morel (xmo) <xmo@odoo.com>
* add configuration for `flake8[flake8-rst-docstring]`
* enable docstring-related checks
* fix invalid docstrings in odoo's core & `base`
* fix a few more bits (mostly missing or incorrect `:param:` info
fields) are out of scope for the lint but my editor catches
closesodoo/odoo#74604
Signed-off-by: Xavier Morel (xmo) <xmo@odoo.com>
Because test cursors are implemented using savepoints, they should *at
most* be nested (ideally they would be strictly sequenced).
If upon being closed a test cursor finds a *different* un-closed
cursor at the top of the stack, one of its followers / children /
descendants was not closed before it, which is a problem.
The initial version of this would look for the cursor being closed in
the stack but this could lead to incoherent cursor stacks and errors
related to the management of the cursors stack, even though it only
exists for reporting reasons.
closesodoo/odoo#76243
Signed-off-by: Xavier Morel (xmo) <xmo@odoo.com>
Initialize the savepoint semi-lazily (on-demand) as cycling a savepoint
generates 4~5 queries (depending whether the savepoint is explicitly
released on COMMIT or not):
SAVEPOINT
-- < do stuff>
-- commit
RELEASE SAVEPOINT -- or not
SAVEPOINT
-- close
ROLLBACK TO SAVEPOINT
RELEASE SAVEPOINT
With a lazy savepoint, this is just 0-1 queries (`SAVEPOINT` at the
first explicit query only, creating a cursor and then closing it
immediately is a no-op).
For reliability use a semi-lazy savepoint: always immediately emit a
`SAVEPOINT` on cursor creation, but don't automatically create one
after each `commit`. That limits the issues of overlapping (but
non-nested) savepoints.
Also fix the `generate` API to not use the request: when `website` was
converted to the new API, `cr`, `uid`, and `context` were dropped as
if it were a model... but it's not. So in order to recover an
execution environment, that was looked up on the session.
That, then, turns out to be an issue when `generate` is triggered from
an RPC call: the RPC layer creates its own cursor and environment
separate from the request's which may not have one at
all. Problematically during testing we're in `mono_db` mode, so the
request's cursor/env can be accessed and will be lazily initialized.
This then causes an issue with the `TestCursor`'s savepoints: rather
than be nested, the lifetimes of the request's and RPC's savepoints
only overlap[0]:
|-- rpc --|
|-- request --|
As a result, when the RPC's cursor is committed and released it
automatically released the request's, and the request's explicit
release then fails. This would break `/website:WithContext.test_search`.
By fixing the API of `generate`, it stops triggering the creation of a
request cursor, and therefore the overlap and resulting error.
[0] the laziness or eagerness of the savepointing in the test cursor
has no impact on this issue, as multiple requests have already been
issued on the RPC's test cursor before the request's is even
created
Part-of: odoo/odoo#76243
Ensure savepoints are *always* released when exiting the context:
rolling back to a savepoint does not release it, so the savepoint
would remain "active" forever (just possibly shadowed).
Also provide a `Savepoint` object to the user, with the following
facilities:
* `name`, in case there are useful things the user can do with a
savepoint name.
The name uses standard UUID representation (rather
than pure hex) because it's otherwise difficult to differentiate
savepoints: in a UUID1, fields 2, 3, and 5 almost certainly don't
change, and the changes between two UUIDs are the last 2-3 nibbles
of field 1 (`time_low`) and the content of field 4 (`seq`, 4 nibbles
at offset 16), with "properly" separated fields it's much easier to
notice the difference.
* `rollback` allows the user to rollback the savepoint to the
initialisation state at any moment.
* `close` allows the use of `contextlib.closing` as well as closing
the savepoint while in the covered span. Closing a savepoint rolls
it back by default (like cursors).
Because there's no such thing as committing a savepoint, it's also
possible to close *without* rolling back, which is similar (but not
identical).
This requires using the semantics of emitting the `SAVEPOINT` during
object initialisation: `closing` was designed to work with non-CMs so
it does not forward `__enter__` to the wrapped object.
Also introduce a CM type for the flushing:
* `_GeneratorContextManager` does not work well when used outside of a
`with`, especially when it yields something: if the CM itself goes
out of scope, the inner generator is `close`d, which raises a
`GeneratorExit` at the `yield` point, which `__exit__`s whichever CM
is held (and in our case would thus rollback and release the
savepoint)
* we probably want to clear() on `rollback`, so having the flushing CM
extend the savepoint one makes a lot of sense
* while it changes the semantics of `Cursor.savepoint` a bit (now
initialises the savepoint at call time instead of delaying until
`__enter__`), it enables the use of `closing` with flushing, and
without having to use the context manager objects directly:
`Cursor.savepoint()` is the only necessary interface, and should
work fine with and without flushing.
Part-of: odoo/odoo#76243
Enabling sql logging for a specific section of code is currently a
pain in the ass as it requires updating both the cursor and the
logger. This utility does that.
This CM is *not* thread-safe as it updates and resets the cursor
without using CAS or anything, so if cursor 1 gets enabled, then
cursor 2, then cursor 1 stops, then cursor 2, cursor 2 will reset the
logger to `logging.DEBUG` which cursor 1 had set, rather than the
probable `logging.NOTSET` it originally was.
Should be possible to fix by e.g. storing the levels in a static
stack (and setting whatever gets popped) buuut... the logging is
already a bit of a mess when multithreaded so I'm unsure it matters
much.
Part-of: odoo/odoo#76243
Refactor the Environments object into a Transaction object, which is
bound to one cursor, and is no longer shared among several cursors.
The following methods/properties have been changed:
- Environment.envs no longer works (because of the design change);
- Environment.manage() is deprecated (no longer useful);
- Environment.reset() is now an instance method;
- env.clear_upon_failure() is deprecated in favor of cr.savepoint().
closesodoo/odoo#75598
Related: odoo/enterprise#20451
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
Co-authored-by: Xavier Dollé <xdo@odoo.com>
This commit adds tooling to profile performance and save execution by
saving stack traces and queries to a file/database in specific format.
----------
Collectors
----------
For now, three different profiling modes (aka Collectors) are available
even if a last once should be introduced by @Gorash to profile qweb
execution.
- SQLCollector (or 'sql'): Saves the current stack trace and the query
every time Cursor.execute() is called. Any query executed on the thread
will be collected, no matter the cursor.
- PeriodicCollector (or 'traces_async'): Saves the stack trace every
'interval' seconds using a parallel thread to profile the caller thread.
The python implementation was optimized to minimize impact on
performance while remaining portable and easy to enable/disable
inside a odoo execution. Higher the frequency (lower the interval),
more impactful the profiling will become on the execution and increase
memory usage. From last experiments, 1ms looks to be a good minimum for
short executions.
- SyncCollector (or 'traces_sync'): Saves the stack trace every function
call/return. This collector is obviously quite impactful on performance
and can quickly overload the memory for long executions, but this is
quite useful to understand the precise path followed by some short
executions. Any time related information will be almost irrelevant with this
collector.
A base Collector defining minimal collectors features can easily be
extended to create custom collectors if needed.
----------------
Profiler & Usage
----------------
Collectors are not supposed to be used by themselves, but should be
given to a Profiler. The Profiler will synchronize collectors starts and
stop, and manage saving them to a file of in a ir_profile in the
database.
Exemple of usage:
```
with Profiler():
do_stuff()
```
This simple example will use the default collectors (sql and
traces_async) and save them to the database. The database is defined
automatically from current_thread 'dbname' if available.
Example of usage:
```
with Profiler(collectors=['sql'], db=False, path=/home/user/logs/do_stuff_profile/{time}):
do_stuff()
```
This more complex example disable the default behavior consisting
to save to the database, gives a path where the profile will be saved
and specify to only use the 'sql' collector. Note that
collectors=[SQLCollector()] would have the same behavior since
Collectors can be either a Collector instance or a string describing the
desired collector. This allows to define custom params for the
collectors and use custom collectors if needed.
Note that it is always possible to get results after execution without
saving it since they are available on the profiler.
```
with Profiler(collectors=['sql'], db=False) as p:
do_stuff()
print(len([None for entry in p.collectors[0].entries if ...]))
```
Profiler will also save the stack below the profiler start point, and
collectors will only collect the part of the stack over this stack.
This is a good way to reduce collectors CPU and memory usage.
Collected entries will be saved as follows:
```
[{
'start': 2.0,
'context': {},
'stack': [
['path_to_file', lno, 'func_name', 'line_content'],
...
],
},
...
]
```
SQLCollector will add three additional keys on each entry:
- query (query without parameters)
- full_query (mogrified query with parameters)
- time (the 'exact' execution time of the query)
----------------
ExecutionContext
----------------
A last tool, ExecutionContext, allows to define some context on some block of code:
Example of usage:
```
def process_modules(modules)
for module in modules:
with ExecutionContext(module=module): # note the 'not linter frienldy but still convenient' 2 spaces indentation
do_stuff(module):
```
This context will automatically be added in the stack as a virtual frame between
process_modules and do_stuff in order to split do_stuff from one single frame to
one frame per module.
----------
Speedscope
----------
The saved data are in a simple json format easy to analyze, but can't be visualized in
speedscope as they are. A utility class `Speedscope` can be used to generate a format
readable by speedscope. The used format is actually the format defined by speedscope,
meaning that all features should be available using it.
The output format is evented, meaning that we need to transform a list of samples
(a list of stack) to a list of event (going in/out a frame).
This is the main task of the Speedscope, as well as combining samples from different
sources, to display SQLCollector and PeriodicCollector results mixed together.
When stored on an ir_profile, the default speedscope generation can easily be generated
with the speedscope computed field.
This class can be used as it is but will mainly be useful for the next commit.
Special thanks to @rco-odoo for the in depth review and @Gorash for support.
Since Odoo 13.0 and the refactor of the internal synchronisation between
the cache and the database, it is unsafe to use the ORM with the cursor
in autocommit mode. The function is deprecated for removal in the
future.
closesodoo/odoo#68313
Task: 2442905
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
The goal of this change is to simplify the code managing `create_date`
and `write_date` in methods `create()` and `write()`, and also to remove
weird behaviors caused by the way those fields were updated.
Assume we update a simple field on a record. This adds pending updates
for the field and `write_date`. However, the value of `write_date` is
not known yet: it will be updated as `NOW() AT TIME ZONE 'UTC'` in SQL.
So `write_date` is actually given a dummy value in pending updates, and
it is invalidated from cache, until its value is flushed to the database
and fetched again.
Now assume we access another field on the record, and that field is not
in cache. The prefetching mechanism will read all column fields,
including `write_date`, and flush them first.
# this adds pending updates foo: 42, write_uid: 1, write_date: False
record.foo = 42
# assume 'bar' is not in cache; this prefetches all column fields,
# which flushes the pending updates above before reading them back
result = record.bar
We can avoid flushing pending updates if the values read from database
do not overwrite existing values in cache. If you assume that the value
of a pending update is in cache (in the example, `foo: 42`), you don't
need to flush the corresponding field. Indeed, the value of `foo` will
remain 42 in cache, whatever its value in the database. This assumption
(pending updates are in cache) is true for all fields *except* for
`write_date`: it is invalidated from cache, and given a dummy value in
pending updates. This branch actually makes this assumption true for
all fields. The avoidance of flushing pending updates will be done in
another commit.
In order to directly assign `write_date` its value, we use a cache for
the value `NOW() AT TIME ZONE 'UTC'` from the database. This costs at
most one query per transaction, and potentially saves a few queries.
Co-authored-by: Victor Feyens <vfe@odoo.com>
Before this change the rollback hooks were never called since rollback() was never explicitely called by the framework. At the end of a transaction, if no error occurs the famework call commit() on the odoo cursor. In all cases, the transaction ends with a call to close(). Into the implementation of _close() rollback() is called on the underlying connection to ensure that not committed changes are rollbacked. That's the reason why despite the fact that rollback() was not called on the Odoo cursor, changes are not committed into the db in case of exception. To keep the same behaviour and avoid to have to explicitely call rollback() on the odoo cursor to trigger the execution of registered rollback hooks, these hooks are now processed in _close(). Since the list of registered hooks is emptied if commit() is called, we are sure that rollback hooks are only executed in case of rollback.
OPW #2294911closesodoo/odoo#60339
X-original-commit: dce9a05f3a5d37fab711c8ca3c5444941f98e814
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
Co-authored-by: Raphael Collet <rco@odoo.com>
This fixes a crash in some controllers with `auth='None'` where some
updates are flushed with an environment where `uid=None`. When there is
an environment with a real uid, preferably use it.
closesodoo/odoo#59658
X-original-commit: 2795c86df54389b858a454cbc1782b1f34f3ba4f
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
Python 3.8 changed the equality rules for bound methods to be based on
the *identity* of the receiver (`__self__`) rather than its *equality*.
This means that in 3.7, methods from different instances will compare
(and hash) equal, thereby landing in the same map "slot", but that isn't
the case in 3.8.
While it's usually not relevant, it's an issue for `GroupCalls` which is
indexed by a function: in 3.7, that being a method from recordsets
comparing equal will deduplicate them, but not anymore in 3.8, leading
to duplicated callbacks (exactly the thing GroupCalls aims to avoid).
Also, the API of `GroupCalls` turned out to be unusual and weird. The
bug above is fixed by using a plain list for callbacks, thereby avoiding
comparisons between registered functions. The API is now:
callbacks.add(func) # add func to callbacks
callbacks.run() # run all callbacks in addition order
callbacks.clear() # remove all callbacks
In order to handle aggregated data, the `callbacks` object provides a
dictionary `callbacks.data` that any callback function can freely use.
For the sake of consistency, the `callbacks.data` dict is automatically
cleared upon execution of callbacks.
Discovered by @william-andre
Related to odoo#56583
References:
* https://bugs.python.org/issue1617161
* python/cpython#7848
* https://docs.python.org/3/whatsnew/changelog.html#python-3-8-0-alpha-1
(no direct link because individual entries are not linkable, look for
bpo-1617161)
X-original-commit: d4b2e9224839aed8fc160ebe5a89e0f7d4c6a5bb
Upon cursor `commit()`, the pending computations are performed with
method `flush()`. However the latter method leaves fields to compute on
new records. As the `commit` ends the current transaction, we can clear
those pending computations.
X-original-commit: d27e98d9048d0cb1250522205286ebc7b7d5ea39
- A bug has been introduced by the PR https://github.com/odoo/odoo/pull/46719
This issue prevented flushes to database when no `uid` is set in the
current environment.
This happens when database changes are made in `auth="none"` routes.
In a MonoDB setup this was working because Odoo consider `None`, `False` as
`null` and was always bound to a database.
Nothing prevents to write `null` in the columns `create_uid` and
`write_uid` in database.
The PR that introduced the bug wanted to block the cases where
`uid` is an instance of the class `RequestUID` to avoid `Cannot adapt
type` errors.
So testing that `uid` is an integer isn't enough.
Two fixes were possible here, either check if `uid` is an instance
of the class `RequestUID` or if it is either an integer, `False` or `None`.
To avoid noise and imports from `odoo`, we test that `uid` is an instance
of `None`.
The case where it is `False` is already tested in the python code:
```python
isinstance(env.uid, int)
```
(manual) forward-port of odoo/odoo#48685closesodoo/odoo#48693
Signed-off-by: Toufik Benjaa (tbe) <tbe@odoo.com>
Signed-off-by: Olivier Dony (odo) <odo@openerp.com>
When routing an HTTP request, the dispatcher uses an environment with a
placeholder for the user (the object `RequestUID`). This environment is
not supposed to be used after routing has been done. However, the
flushing function takes any environment with a given cursor, and it
crashes when this environment is chosen (`psycopg2` cannot adapt the
type `RequestUID` for `write_uid`), and simply does not make sense.
closesodoo/odoo#48495
X-original-commit: da61a64bf6731a08557d23680eabf4d910035ebd
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
The `__closer` attribute is filled with the origin of a call to
`cr.close()`. That information is reused in the `check` decotator that
ensure the user is not using a closed cursor. In case he is using a
closed cursor, an error is raised with that optional origin in case of
`--log-sql`.
The attribute is a dundler so it is only accessible within its class, as
the decorator has been moved outside of the class by 058cf208a8 it is
not directly accessible thus `__getattr__` is called as a fallback. The
`__getattr__` itself is protected by the `check` decorator thus they
call each other in a infinite recursion.
As the related dundler is no more used internally, it has been decided
to remove it entirely.
closesodoo/odoo#47616
Task: 2199895
X-original-commit: 3ebf7cb9cca37b05f44aaffc0b1f289cc65f300f
Signed-off-by: Julien Castiaux <Julien00859@users.noreply.github.com>
Starting with Python 3, queries sent by psyocopg2 are stored as `bytes()` objects.
Logging those raw makes them appear unformatted, harder to read than in v10 or lower Odoo versions (i.e. `\n` instead of a raw newline character).
Decoding the query into unicode makes it easier to read in the logs.
closesodoo/odoo#38074
X-original-commit: 329accde2ed6d4dbfdde6d3d99d71e21d15396b7
Signed-off-by: Christophe Simonis <chs@odoo.com>
[`psycopg2` includes a submodule called `sql`][1] which provides more safety and comfort when dealing with raw SQL queries.
As of today, it works fine with Odoo unless SQL query logging is enabled.
This patch fixes that problem, allowing usage of that module.
[1]: http://initd.org/psycopg/docs/sql.htmlclosesodoo/odoo#37561
Signed-off-by: Christophe Simonis <chs@odoo.com>
When creating a new database from the database manager, with no open
cursor, the wrong env was retrieved during the cr.commit() call.
2019-09-09 18:16:07,454 19886 ERROR None odoo.service.db: CREATE DATABASE failed:
Traceback (most recent call last):
File "/home/odoo/odoo/service/db.py", line 60, in _initialize_db
cr.commit()
File "/home/odoo/odoo/sql_db.py", line 165, in wrapper
return f(self, *args, **kwargs)
File "/home/odoo/odoo/sql_db.py", line 389, in commit
env = get_env(currentframe(), 2)
File "/home/odoo/odoo/sql_db.py", line 72, in get_env
env = getattr(frame.f_locals.get('self'), 'env', SENTINEL)
File "/home/odoo/odoo/http.py", line 268, in env
self._env = odoo.api.Environment(self.cr, self.uid, self.context)
File "/home/odoo/odoo/http.py", line 238, in cr
raise RuntimeError('request not bound to a database')
get_env method checks every frame to find a variable called 'env'
As none was found, it used the one of the WebRequest object.
In a WebRequest, env is a property that will try to create a new
Environment, which fails as no database is available (yet).
At eafdf1812d the iteration on Environment.envs was removed as envs
is a weakset and it introduced potential errors where the content was
garbage-collected during the iteration.
Go back to the simpler iteration but convert the set to list to avoid
garbage-collection issues.
Fixesodoo/odoo#36588closesodoo/odoo#37005
Signed-off-by: Martin Trigaux (mat) <mat@odoo.com>
Co-authored-by: Raphael Collet <rco@odoo.com>
ee03fc3770 introduced a non deterministic bug by choosing an
environment in a set, so the environment is not always the good one.
closesodoo/odoo#36056
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
This branch is the combination of several optimizations in the ORM:
* store field values once in the cache: the cache reflects more
faithfully the database, only fields that explicitly depend on the
context have an extra indirection in the cache;
* delay recomputations by default: use method `recompute` to explicitly
flush out pending recomputations;
* delay updates in method `write`: updates are stored in a data
structure that can be flushed efficiently to the database with method
`flush` (which also flush out recomputations);
* make method `modified` take advantage of inverse fields to inverse
dependencies;
* filter records by evaluating a domain on records in Python;
* a computed field with `readonly=False` behaves like a normal field
with an onchange method;
* computed fields are computed in superuser mode by default.
Work done by Toufik Ben Jaa, Raphael Collet, Denis Ledoux and Fabien
Pinckaers.
closesodoo/odoo#35659
Signed-off-by: Denis Ledoux <beledouxdenis@users.noreply.github.com>
This commit replaces calls to pycompat helpers that were intended for
python 2 <-> python 3 interoperability for python 3 builtins, as python
2 is no longer officially supported by Odoo.
This includes:
* calls to imap/izip/ifilter replaced by map/zip/filter
* uses of text_type replaced by str
* uses of unichr replaced by chr
* calls to implements_to_string, implements_iterator removed
* string_types and integer_types replaced by str, int respectively
* calls to to_native replaced by calls to to_text
This is done in preparation to the removal of these deprecated helpers
in the following commit.
When there is a performance issue, it's sometimes difficult to discover
which request increased the query count or its duration.
With this commit, the query count, the query time and "python and io" time are displayed
in the logs at the end of each werkzeug request line.
Co-authored-by: Christophe Monniez <moc@odoo.com>
From this commit onwards, Date fields will return datetime.date objects and Datetime fields will return datetime.datetime objects, this implies a number of things that are clearly explained both in the ORM API for master.
This commit also introduces a number of helper functions for dates and datetimes that are exposed in tools.date_utils and fields.Date[time], explained in the documentation as well.
Task-ID: 47189
Since 1a58e108 (on 10.0 and over) parameters are no longer present when
logging sql queries.
This removes some of the usefulness of the feature, and this commit adds
them back.
Since mogrify returns a byte string in the database encoding, we decode
it using the corresponding python encoding.
opw-1839241
closes#24446
This allows rpc requests in `HttpCase` to use the cursor `self.cr`, which is
now shared between the Python test and the rpc requests. This simplifies code
to prepare a JS test, and code to check the result of a JS tour.
Fixes#12237
Now that we're closer to switching to P3 for good, these helpers have
outlived their usefulness, and mostly add noise.
All remaining dict.iter*() or dict.view*() must be converted to the
normal keys(), values() or items() calls.
Whenever the result is likely to be used for more than the scope of a
loop, or when the dict needs to be modified during iteration, the calls
must be wrapped in a ``list()``, to protect the new P3 semantics.
Those cases are very exceptional.
Also removed some dead code or improved the API to remove unnecessary
conversions.
Moisés López