Purge session command stuck in the process

[Nicolas MARTIN]

Hello Trac users


I just tried to clean up a little the amount of anonymous sessions
stored in the database but each attempt seems to be ending up in a dead
end. Have to kill the process after some time without clear evolution.

After setting the good options to output the log in the console
('[logging] log_type = stderr' Don't even know this tip !), I got the
whole process but the issue remains undetermined to me. Trac loads its
environment with the installed plugins and the last 2 lines are about
the default workflow and the database:

'
...
20:55:03 Trac[default_workflow] DEBUG: Workflow actions at
initialization: {u'resolve': {u'operations': [u'set_resolution'],
'name': u'resolve', u'default': 998, 'newstate': u'closed', 'oldstates':
[u'assigned', u'new', u'reopened'], u'permissions': [u'TICKET_MODIFY']},
u'accept': {u'operations': [u'set_owner_to_self'], 'name': u'accept',
u'default': 997, 'newstate': u'assigned', 'oldstates': [u'new',
u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'leave':
{u'operations': [u'leave_status'], 'name': u'leave', u'default': 1000,
'newstate': u'*', 'oldstates': [u'assigned', u'new', u'reopened',
u'closed'], 'permissions': []}, u'reopen': {u'operations':
[u'del_resolution'], 'name': u'reopen', u'default': 996, 'newstate':
u'reopened', 'oldstates': [u'closed'], u'permissions':
[u'TICKET_CREATE']}, u'reassign': {u'operations': [u'set_owner'],
'name': u'reassign', u'default': 999, 'newstate': u'assigned',
'oldstates': [u'assigned', u'new', u'reopened'], u'permissions':
[u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'],
'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [],
'permissions': []}}
20:55:03 Trac[tracdb] DEBUG: "FormDBComponent" does not need a schema
upgrade.
'

Regards,
Nicolas

[Nicolas MARTIN]

Sorry, I forgot to put the involved command if necessary:

trac-admin ~/trac/ session purge "01/01/15 00:00:00"

[Ryan Ollos]

Session purge could take a little time to execute if you have many anonymous sessions, as may occur due to bots with a publicly-accessible site. How long did you let the command run for?

If you have an SQLite database the command will lock the database and therefore the site will not be accessible while the command is executing.

If you want to know how many sessions exist you can check using a command line tool such as sqlite3.

$ sqlite3 ~/trac/db/trac.db

sqlite> SELECT COUNT(*) FROM session;

- Ryan

[Nicolas MARTIN]

That's the first time I look into this, there is about ~63 000 sessions in the database (PostgreSQL).

For the availability of the platform, it is kind of the right time because we are well out of working hours here.

For my first attempts, don't know exactly the time I let but it is a matter of 1 minute.

Nicolas

--
You received this message because you are subscribed to the Google Groups "Trac Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to trac-users+...@googlegroups.com.
To post to this group, send email to trac-...@googlegroups.com.
Visit this group at https://groups.google.com/group/trac-users.
For more options, visit https://groups.google.com/d/optout.

[Nicolas MARTIN]

Well finally the system completed the command (almost 8 minutes)

'

22:35:40 Trac[tracdb] DEBUG: "FormDBComponent" does not need a schema upgrade.

real    8m25.808s
user    0m0.850s
sys    0m0.080s

'

The funny thing is that it has removed almost none sessions during that time :-/

[RjOllos]

On Tuesday, October 10, 2017 at 1:49:30 PM UTC-7, Nicolas MARTIN wrote:

Well finally the system completed the command (almost 8 minutes)

'

22:35:40 Trac[tracdb] DEBUG: "FormDBComponent" does not need a schema upgrade.

real    8m25.808s
user    0m0.850s
sys    0m0.080s

'

The funny thing is that it has removed almost none sessions during that time :-/

Approximately how many sessions were removed?

It might be that the datetime format you used is not correct for your host. You can see the valid localized format in the help text:

$trac-admin ../tracenvs/proj-1.0 help session purge

session purge <age>

    Purge anonymous sessions older than the given age or date

    Age may be specified as a relative time like "90 days ago", or as a date in

    the "MMM d, y, h:mm:ss a" or "YYYY-MM-DDThh:mm:ss±hh:mm" (ISO 8601) format.

You could use "3 years ago" for the age, to get close to the effect of "01/01/15 00:00:00" 

- Ryan

[Nicolas MARTIN]

There was no surprise regarding the number of sessions removed (almost zero),  the site has been released publicly a few months ago.
My command was just for testing purpose but I didn't expect it would take some much time with no substantial operations on the db.

In fact, we have a mean of 500 sessions created per day since putting it online. I decided to cut by half and kept the sessions only since September,
I'm not sure if we have an interest of keeping them.

The weird thing is that the command took about 4 mins while parsing the same number of sessions.

Nicolas

[RjOllos]

On Wednesday, October 11, 2017 at 3:33:23 AM UTC-7, Nicolas MARTIN wrote:

There was no surprise regarding the number of sessions removed (almost zero),  the site has been released publicly a few months ago.
My command was just for testing purpose but I didn't expect it would take some much time with no substantial operations on the db.

In fact, we have a mean of 500 sessions created per day since putting it online. I decided to cut by half and kept the sessions only since September,
I'm not sure if we have an interest of keeping them.

The weird thing is that the command took about 4 mins while parsing the same number of sessions.

Nicolas

You could see what queries are being executed by setting:

[logging]

log_level = DEBUG

[trac]

debug_sql  = enabled

You should get just two queries:

11:23:58 Trac[util] DEBUG: SQL:
                DELETE FROM session
                WHERE authenticated=0 AND last_visit<%s

11:23:58 Trac[util] DEBUG: args: (1444674238,)
11:23:58 Trac[util] DEBUG: prefetch: 0 rows
11:23:58 Trac[util] DEBUG: SQL:
                DELETE FROM session_attribute
                WHERE authenticated=0
                      AND sid NOT IN (SELECT sid FROM session
                                      WHERE authenticated=0)

- Ryan

[Nicolas MARTIN]

Back to this thread, I launched a anonymous sessions purge with your recommended options:

$ psql -c "SELECT COUNT(*) FROM session;"
 count 
-------
 32107
$ time trac-admin ~/trac/ session purge "01/01/15 00:00:00"
17:43:22 Trac[env] INFO: -------------------------------- environment startup [Trac 1.0.1] --------------------------------
...
17:43:23 Trac[util] DEBUG: SQL: 
                DELETE FROM session
                WHERE authenticated=0 AND last_visit<%s                

17:43:23 Trac[util] DEBUG: args: (1420066800,)*
17:43:23 Trac[util] DEBUG: SQL: 
                DELETE FROM session_attribute
                WHERE authenticated=0
                      AND sid NOT IN (SELECT sid FROM session
                                      WHERE authenticated=0)

real    1m54.222s
user    0m0.760s
sys    0m0.120s

$ psql -c "SELECT COUNT(*) FROM session;"
 count 
-------
 32108

It took all the time (~2 mns) in the second DELETE operation because it wasn't expecting to find a session previous to 01-01-2015.
I have repeated the same command third times with a similar running time.

Then I modified the command to remove anonymous sessions from last September and it took almost the same time

$ time trac-admin ~/trac/ session purge "09/01/17 00:00:00"
18:34:31 Trac[env] INFO: -------------------------------- environment startup [Trac 1.0.1] --------------------------------
...
18:34:32 Trac[util] DEBUG: SQL: 
                DELETE FROM session
                WHERE authenticated=0 AND last_visit<%s                

18:34:32 Trac[util] DEBUG: args: (1504216800,)
18:34:32 Trac[util] DEBUG: SQL: 
                DELETE FROM session_attribute
                WHERE authenticated=0
                      AND sid NOT IN (SELECT sid FROM session
                                      WHERE authenticated=0)
real    1m55.482s
user    0m0.790s
sys    0m0.090s

[nemo@forge ~]$ psql -c "SELECT COUNT(*) FROM session;"
 count 
-------
 32116

I'm quite a newbie in SQL stuff but from my standpoint these 2 minutes are much too long for parsing the database.

Couldn't we have a hidden issue here ?

[Nicolas MARTIN]

Finally I cut by three the number of remaining anonymous sessions (~10 000) in order to get a workable running time, by this I hope to improve the overall behavior of Trac.
I set '1 month ago' in trac-admin purge argument and insert the command in the cron.

Maybe it won't stay that way in the future.

Nicolas

[Jun Omae]

On Tue, Nov 7, 2017 at 2:52 AM, Nicolas MARTIN <ntm...@locean.upmc.fr> wrote:
> $ time trac-admin ~/trac/ session purge "09/01/17 00:00:00"
> 18:34:31 Trac[env] INFO: -------------------------------- environment
> startup [Trac 1.0.1] --------------------------------
> ...
> 18:34:32 Trac[util] DEBUG: SQL:
> DELETE FROM session
> WHERE authenticated=0 AND last_visit<%s
>
> 18:34:32 Trac[util] DEBUG: args: (1504216800,)
> 18:34:32 Trac[util] DEBUG: SQL:
> DELETE FROM session_attribute
> WHERE authenticated=0
> AND sid NOT IN (SELECT sid FROM session
> WHERE authenticated=0)
> real 1m55.482s
> user 0m0.790s
> sys 0m0.090s
>
> [nemo@forge ~]$ psql -c "SELECT COUNT(*) FROM session;"
> count
> -------
> 32116
>
> I'm quite a newbie in SQL stuff but from my standpoint these 2 minutes are
> much too long for parsing the database.
>
> Couldn't we have a hidden issue here ?

Could you please share results of the following explain queries?

====
EXPLAIN DELETE FROM session WHERE authenticated=0 AND last_visit<1504216800;

EXPLAIN DELETE FROM session_attribute
WHERE authenticated=0
AND sid NOT IN (SELECT sid FROM session WHERE authenticated=0);
====

--
Jun Omae <jun...@gmail.com> (大前 潤)

[Nicolas MARTIN]

Here you are

$ psql -c "EXPLAIN DELETE FROM session WHERE authenticated=0 AND last_visit<1504216800;"
                             QUERY PLAN
---------------------------------------------------------------------
 Delete on session  (cost=0.00..931.79 rows=1506 width=6)
   ->  Seq Scan on session  (cost=0.00..931.79 rows=1506 width=6)
         Filter: ((last_visit < 1504216800) AND (authenticated = 0))

$ psql -c "EXPLAIN DELETE FROM session_attribute WHERE authenticated=0 AND sid NOT IN (SELECT sid FROM session WHERE authenticated=0);"
                                  QUERY PLAN
-------------------------------------------------------------------------------
 Delete on session_attribute  (cost=926.96..3379.66 rows=7889 width=6)
   ->  Seq Scan on session_attribute  (cost=926.96..3379.66 rows=7889 width=6)
         Filter: ((NOT (hashed SubPlan 1)) AND (authenticated = 0))
         SubPlan 1
           ->  Seq Scan on session  (cost=0.00..901.83 rows=10052 width=22)
                 Filter: (authenticated = 0)

It's probably not as informative as it could be after my last purge of
anonymous sessions.


Nicolas

[Jun Omae]

On Tue, Nov 7, 2017 at 7:41 PM, Nicolas MARTIN <ntm...@locean.upmc.fr> wrote:
> > Here you are
> >
> > $ psql -c "EXPLAIN DELETE FROM session WHERE authenticated=0 AND
> > last_visit<1504216800;"
> > QUERY PLAN
> > ---------------------------------------------------------------------
> > Delete on session (cost=0.00..931.79 rows=1506 width=6)
> > -> Seq Scan on session (cost=0.00..931.79 rows=1506 width=6)
> > Filter: ((last_visit < 1504216800) AND (authenticated = 0))
> >
> > $ psql -c "EXPLAIN DELETE FROM session_attribute WHERE authenticated=0 AND
> > sid NOT IN (SELECT sid FROM session WHERE authenticated=0);"
> > QUERY PLAN
> > -------------------------------------------------------------------------------
> > Delete on session_attribute (cost=926.96..3379.66 rows=7889 width=6)
> > -> Seq Scan on session_attribute (cost=926.96..3379.66 rows=7889
> > width=6)
> > Filter: ((NOT (hashed SubPlan 1)) AND (authenticated = 0))
> > SubPlan 1
> > -> Seq Scan on session (cost=0.00..901.83 rows=10052 width=22)
> > Filter: (authenticated = 0)
> >
> > It's probably not as informative as it could be after my last purge of
> > anonymous sessions.

Thanks for the reply.

It seems that "NOT IN (...)" in delete query for session_attribute leads the issue.
I consider it could be solved by using "NOT EXISTS (...)", instead.

====
diff --git a/trac/web/session.py b/trac/web/session.py
index a8b68fae6..103c22c4a 100644
--- a/trac/web/session.py
+++ b/trac/web/session.py
@@ -500,6 +500,7 @@ class SessionAdmin(Component):
db("""

DELETE FROM session_attribute
WHERE authenticated=0

- AND sid NOT IN (SELECT sid FROM session
- WHERE authenticated=0)
+ AND NOT EXISTS (SELECT * FROM session AS s
+ WHERE s.sid=session_attribute.sid
+ AND s.authenticated=0)
""")
====

I tested with 100,000 sessions on PostgreSQL.

trac=> SELECT authenticated, COUNT(*) FROM session GROUP BY authenticated;
authenticated | count
---------------+--------
0 | 100000
1 | 9
(2 rows)

trac=> SELECT authenticated, COUNT(*) FROM session_attribute GROUP BY
authenticated;
authenticated | count
---------------+--------
0 | 200000
1 | 47
(2 rows)

trac=> \timing on
Timing is on.
trac=> BEGIN;
BEGIN
Time: 0.276 ms
trac=> DELETE FROM session_attribute
trac-> WHERE authenticated=0
trac-> AND sid NOT IN (SELECT sid FROM session
trac(> WHERE authenticated=0)
trac-> ;
^CCancel request sent
ERROR: canceling statement due to user request
Time: 555742.893 ms
trac=>
trac=>
trac=> BEGIN;
BEGIN
Time: 0.288 ms
trac=> DELETE FROM session_attribute
trac-> WHERE authenticated=0
trac-> AND NOT EXISTS (SELECT * FROM session AS s
trac(> WHERE s.sid=session_attribute.sid
trac(> AND s.authenticated=0)
trac-> ;
DELETE 0
Time: 161.881 ms
trac=> ROLLBACK;
ROLLBACK
Time: 0.263 ms


trac=> EXPLAIN
trac-> DELETE FROM session_attribute
trac-> WHERE authenticated=0
trac-> AND sid NOT IN (SELECT sid FROM session
trac(> WHERE authenticated=0)
trac-> ;
QUERY PLAN
-----------------------------------------------------------------------------------
Delete on session_attribute (cost=0.00..242228398.61 rows=75356 width=6)
-> Seq Scan on session_attribute (cost=0.00..242228398.61 rows=75356 width=6)
Filter: ((authenticated = 0) AND (NOT (SubPlan 1)))
SubPlan 1
-> Materialize (cost=0.00..3088.90 rows=50048 width=32)
-> Seq Scan on session (cost=0.00..2495.66 rows=50048 width=32)
Filter: (authenticated = 0)
(7 rows)

trac=> EXPLAIN
trac-> DELETE FROM session_attribute
trac-> WHERE authenticated=0
trac-> AND NOT EXISTS (SELECT * FROM session AS s
trac(> WHERE s.sid=session_attribute.sid
trac(> AND s.authenticated=0)
trac-> ;
QUERY PLAN
--------------------------------------------------------------------------------------
Delete on session_attribute (cost=3512.26..14370.02 rows=53393 width=12)
-> Hash Anti Join (cost=3512.26..14370.02 rows=53393 width=12)
Hash Cond: (session_attribute.sid = s.sid)
-> Seq Scan on session_attribute (cost=0.00..6430.10 rows=150713 width=38)
Filter: (authenticated = 0)
-> Hash (cost=2495.66..2495.66 rows=50048 width=38)
-> Seq Scan on session s (cost=0.00..2495.66 rows=50048 width=38)
Filter: (authenticated = 0)
(8 rows)