View Issue Details

WikiRelated ChangesetsJump to Notes
IDProjectCategoryView StatusDate SubmittedLast Update
0026600mantisbtperformancepublic2020-01-16 07:522020-03-15 15:23
Reportertk Assigned Todregad  
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionfixed 
Product Version2.23.0 
Target Version2.23.1Fixed in Version2.23.1 
Summary0026600: Performance loss after update from 2.20.0 to 2.23.0
Description

After upgrade from 2.20.0 to 2.23.0 I see heavy performance loss, especially if issues with many notes and/or long history are affected.

As an example I have one issue with a history list of approx 400 items ( due to cloning ). The issue does not contain any notes or attachements. In 2.20.0, the issue opens instantaneously, in 2.23.0 it takes more than 30sec.

There are no error messages in apache logs.
As well, there are no php errors ( I've activated php error display by



$g_display_errors = array(

E_RECOVERABLE_ERROR => DISPLAY_ERROR_HALT,

E_WARNING           => DISPLAY_ERROR_HALT,

E_ALL               => DISPLAY_ERROR_INLINE,

);
)

[atrol EDIT] according 0026600:0063448

Steps To Reproduce

Site Information
MantisBT Version 2.23.0
Schema Version 210
PHP Version 7.2.11
Database Driver mysqli
Database Version, Description 5.6.19, 5.6.19-log

Apart from mantis release there is no difference in the mantis / LAMP environment between mantis installations. Tested installations access the same mysql-DB.

Additional Information

Problem causes negative user feedback

TagsNo tags attached.

Relationships

related to 0025902 closedvboctor Implement IssueViewPageCommand to separate logic from rendering of issue view page 
child of 0026622 closeddregad LDAP API does not cache realname information 

Activities

dregad

dregad

2020-01-16 10:28

developer   ~0063447

I see heavy performance loss

Can you enable SQL logging with $g_log_level = LOG_DATABASE and compare the results between the 2 instances, to pinpoint the query(ies) that are causing the problem

Tested installations access the same mysql-DB.

Considering that 2.23.0 requires a schema update, that seems odd - did you run the installer after upgrading ?

there are php errors

Can you be more specific and provide details about those e.g. with $g_show_detailed_errors = ON ?

tk

tk

2020-01-17 01:55

reporter   ~0063448

Last edited: 2020-01-17 01:57

Regading php errors: thats a typo, I meant "As well, there are /no/ php errors ...", sorry.

Regarding schema:
Yes, I run the installer ( admin/install.php ). The procedure gave neither positive nor negative feedback in the form of executed changes, redirecting me to the login page with the message that now I could login. I was used to some action reports about executed changes in the past, so I'm not sure whether the schema update has been executed really successfully. Is there some way to validate that the DB schema?
After each update I try and consult admin/check/, but I don't see anything that might point to database or schema.

I'll try and do compare the DB access logs, but I suppose that's going to produce masses of data in my case.
atrol

atrol

2020-01-17 02:13

developer   ~0063449

Last edited: 2020-01-17 02:14

but I don't see anything that might point to database or schema.

Click on Manage to get some site information including the database schema version.
tk

tk

2020-01-17 02:30

reporter   ~0063450

Last edited: 2020-01-17 02:35

I had added the "manage" site information in the steps to reproduce, only the paths have been omitted
atrol

atrol

2020-01-17 02:37

developer   ~0063451

Schema Version 210 is fine.

Waiting for your feedback to 0026600:0063447 concerning SQL logging.
dregad

dregad

2020-01-17 05:11

developer   ~0063457

Regading php errors: thats a typo, I meant "As well, there are /no/ php errors ...", sorry.

OK.

The procedure gave neither positive nor negative feedback in the form of executed changes

It should have displayed a line indicating that for schema step 210 a column was added to bug_file table.

Is there some way to validate that the DB schema?
I had added the "manage" site information in the steps to reproduce, only the paths have been omitted

Sorry I missed that. MantisBT <= 2.22 has schema version 209, 2.23 is 210, everything should be fine.

I'll try and do compare the DB access logs, but I suppose that's going to produce masses of data in my case.

You can minimize the log's volume, by clearing the log file first and only enable logging just before reproducing the problem and deactivate after that (best in a system that is not actively used by other users of course).
tk

tk

2020-01-17 05:12

reporter   ~0063458

Attached you find the SQL logging of access to my probe issue. Regarding SQL timing I find nothing unhealthy.

Therefore I did another run in 2.23.0 of the same access, watching the log via tail. I see inactivity in the log ( and on the mantis display ) between two following entries in the SQL log ( the minute based timestamps are too coarse ):

2020-01-17 10:56 CET DB user_api.php:130 user_cache_array_rows() array (
0 => 'SELECT * FROM mantis_user_table WHERE id IN (0)',
1 => '0.0005',
)

[ nothing happens for some time, so here the time must get lost ]

2020-01-17 10:57 CET DB user_api.php:376 user_is_monitoring_bug() array (
0 => 'SELECT COUNT(*) FROM mantis_bug_monitor_table
WHERE user_id=764 AND bug_id=56810',
1 => '0.0004',
)

mantis.2.20.0.log (15,323 bytes)    
2020-01-17 10:45 CET DB database_api.php:161 db_connect() array (
  0 => 'SET NAMES UTF8',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB plugin_api.php:906 plugin_register_installed() array (
  0 => 'SELECT basename, priority, protected FROM mantis_plugin_table WHERE enabled=\'1\' ORDER BY priority DESC',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB authentication_api.php:1062 auth_is_cookie_valid() array (
  0 => 'SELECT * FROM mantis_user_table WHERE cookie_string=\'2a94a6b0b3333fcc3978e0e2f275b7797c4e1485e64a15e8febf0833af7e7b24\'',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB user_pref_api.php:334 user_pref_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_pref_table WHERE user_id IN (764) AND project_id = 0',
  1 => '0.0017',
)
2020-01-17 10:45 CET DB project_api.php:109 project_cache_row() array (
  0 => 'SELECT * FROM mantis_project_table WHERE id=\'157\'',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB config_api.php:728 config_cache_all() array (
  0 => 'SELECT config_id, user_id, project_id, type,  value, access_reqd FROM mantis_config_table',
  1 => '0.0015',
)
2020-01-17 10:45 CET DB tokens_api.php:254 token_purge_expired() array (
  0 => 'DELETE FROM mantis_tokens_table WHERE 1579254351 > expiry',
  1 => '0.0006',
)
2020-01-17 10:45 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=5 AND owner=764',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_api.php:868 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=56810',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_api.php:975 bug_text_cache_row() array (
  0 => 'SELECT bt.* FROM mantis_bug_text_table bt, mantis_bug_table b
				  WHERE b.id=56810 AND b.bug_text_id = bt.id',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB project_hierarchy_api.php:167 project_hierarchy_cache() array (
  0 => 'SELECT DISTINCT p.id, ph.parent_id, p.name, p.inherit_global, ph.inherit_parent
				  FROM mantis_project_table p
				  LEFT JOIN mantis_project_hierarchy_table ph
				    ON ph.child_id = p.id
				  WHERE p.enabled = \'1\'
				  ORDER BY p.name',
  1 => '0.0010',
)
2020-01-17 10:45 CET DB user_api.php:1174 user_get_accessible_subprojects() array (
  0 => 'SELECT DISTINCT p.id, p.name, ph.parent_id
					  FROM mantis_project_table p
					  LEFT JOIN mantis_project_hierarchy_table ph
					    ON ph.child_id = p.id
					  WHERE p.enabled = \'1\' AND
					  	 ph.parent_id IS NOT NULL
					  ORDER BY p.name',
  1 => '0.0008',
)
2020-01-17 10:45 CET DB project_api.php:149 project_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_project_table WHERE id IN (169,126,331,288,290,162,285,340,59,93,313,270,207,160,277,60,299,179,346,159,74,222,11,68,109,49,2,6,47,14,155,156,188,338,172,163,3,158,282,268,321,297,190,258,189,320,342,127,339,212,234,269,240,237,215,221,235,204,231,350,343,223,198,317,196,178,187,281,173,337,181,312,316,267,182,303,286,326,306,275,304,324,323,322,325,192,251,193,289,291,203,220,305,202,205,296,161,308,341,89,211,276,236,327,264,352,345,265,266,332,328,329,314,315,318,319,271,284,272,208,259,233,216,229,241,217,245,244,248,246,243,242,249,247,351,311,310,333,301,25,26,307,298,336,353,335,334,278,230,200,201,300,180,349,348,347,53,4,279,69,261,255,124,210,262,118,254,302,123,330,175,174,280,219,309,273,54,61)',
  1 => '0.0009',
)
2020-01-17 10:45 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB version_api.php:238 version_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_project_version_table WHERE project_id IN (157,0)',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB category_api.php:306 category_get_row() array (
  0 => 'SELECT * FROM mantis_category_table WHERE id=523',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (966)',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB access_api.php:163 access_cache_matrix_user() array (
  0 => 'SELECT project_id, access_level FROM mantis_project_user_list_table WHERE user_id=966',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB project_api.php:687 project_get_all_user_rows() array (
  0 => 'SELECT id, username, realname, access_level
				FROM mantis_user_table
				WHERE enabled = 1
					AND access_level >= 90 ',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB project_api.php:702 project_get_all_user_rows() array (
  0 => 'SELECT u.id, u.username, u.realname, l.access_level
				FROM mantis_project_user_list_table l, mantis_user_table u
				WHERE l.user_id = u.id
				AND u.enabled = 1
				AND l.project_id = 157',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB user_api.php:376 user_is_monitoring_bug() array (
  0 => 'SELECT COUNT(*) FROM mantis_bug_monitor_table
				  WHERE user_id=764 AND bug_id=56810',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB tag_api.php:139 tag_cache_bug_tag_rows() array (
  0 => 'SELECT B.id AS bug_id, BT.tag_id, BT.user_id, BT.date_attached FROM mantis_bug_table B LEFT OUTER JOIN mantis_bug_tag_table BT ON B.id=BT.bug_id WHERE B.id IN (56810)',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB tag_api.php:713 tag_get_candidates_for_bug() array (
  0 => 'SELECT id, name, description FROM mantis_tag_table WHERE id IN (
					SELECT t.id FROM mantis_tag_table t
					LEFT JOIN mantis_bug_tag_table b ON t.id=b.tag_id
					WHERE b.bug_id IS NULL OR b.bug_id != 56810) ORDER BY name ASC ',
  1 => '0.0011',
)
2020-01-17 10:45 CET DB custom_field_api.php:817 custom_field_get_linked_ids() array (
  0 => 'SELECT CFP.project_id, CF.id FROM mantis_custom_field_table CF  JOIN mantis_custom_field_project_table CFP ON CFP.field_id = CF.id WHERE CFP.project_id IN (157)	ORDER BY sequence ASC, name ASC',
  1 => '0.0006',
)
2020-01-17 10:45 CET DB relationship_api.php:444 relationship_get_all_src() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.destination_bug_id = mantis_bug_table.id
				WHERE source_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB relationship_api.php:485 relationship_get_all_dest() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.source_bug_id = mantis_bug_table.id
				WHERE destination_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB bug_api.php:2090 bug_get_monitors() array (
  0 => 'SELECT user_id, enabled
			FROM mantis_bug_monitor_table m, mantis_user_table u
			WHERE m.bug_id=56810 AND m.user_id = u.id
			ORDER BY u.realname, u.username',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB access_api.php:132 access_cache_matrix_project() array (
  0 => 'SELECT user_id, access_level FROM mantis_project_user_list_table WHERE project_id=157',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB bug_api.php:1727 bug_get_attachments() array (
  0 => 'SELECT id, title, diskfile, filename, filesize, file_type, date_added, user_id
		                FROM mantis_bug_file_table
		                WHERE bug_id=56810
		                ORDER BY date_added',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bugnote_api.php:613 bugnote_get_all_bugnotes() array (
  0 => 'SELECT b.*, t.note
			          	FROM      mantis_bugnote_table b
			          	LEFT JOIN mantis_bugnote_text_table t ON b.bugnote_text_id = t.id
						WHERE b.bug_id=56810
						ORDER BY b.date_submitted ASC, b.id ASC',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB history_api.php:272 history_query_result() array (
  0 => 'SELECT * FROM mantis_bug_history_table WHERE mantis_bug_history_table.bug_id = 56810 ORDER BY mantis_bug_history_table.date_modified ASC, mantis_bug_history_table.id ASC',
  1 => '0.0032',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (430)',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (31)',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (679)',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (921)',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (920)',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_api.php:868 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=59490',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (11)',
  1 => '0.0009',
)
2020-01-17 10:45 CET DB user_api.php:132 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (511)',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_api.php:868 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=60920',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=49749',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=49952',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=51152',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52371',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52372',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52373',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52422',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52444',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52644',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52699',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52854',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53088',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53426',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53429',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53441',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54197',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54473',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54609',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54783',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55690',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55691',
  1 => '0.0005',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55770',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=57066',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=57073',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=58167',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=58484',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=60672',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=60688',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=61098',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=64566',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB user_api.php:1489 user_update_last_visit() array (
  0 => 'UPDATE mantis_user_table SET last_visit=1579254351 WHERE id=764',
  1 => '0.0010',
)
2020-01-17 10:45 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0004',
)
2020-01-17 10:45 CET DB tokens_api.php:49 token_exists() array (
  0 => 'SELECT id FROM mantis_tokens_table WHERE id=\'144352\'',
  1 => '0.0003',
)
2020-01-17 10:45 CET DB tokens_api.php:222 token_update() array (
  0 => 'UPDATE mantis_tokens_table
					SET value=\'56810\', expiry=1579340751
					WHERE id=144352',
  1 => '0.0012',
)
mantis.2.20.0.log (15,323 bytes)   
mantis.2.23.0.log (17,345 bytes)    
2020-01-17 10:39 CET DB database_api.php:161 db_connect() array (
  0 => 'SET NAMES UTF8',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB plugin_api.php:910 plugin_register_installed() array (
  0 => 'SELECT basename, priority, protected FROM mantis_plugin_table WHERE enabled=\'1\' ORDER BY priority DESC',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB authentication_api.php:1062 auth_is_cookie_valid() array (
  0 => 'SELECT * FROM mantis_user_table WHERE cookie_string=\'2a94a6b0b3333fcc3978e0e2f275b7797c4e1485e64a15e8febf0833af7e7b24\'',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB user_pref_api.php:334 user_pref_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_pref_table WHERE user_id IN (764) AND project_id = 0',
  1 => '0.0011',
)
2020-01-17 10:39 CET DB project_api.php:109 project_cache_row() array (
  0 => 'SELECT * FROM mantis_project_table WHERE id=\'157\'',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB config_api.php:728 config_cache_all() array (
  0 => 'SELECT config_id, user_id, project_id, type,  value, access_reqd FROM mantis_config_table',
  1 => '0.0016',
)
2020-01-17 10:39 CET DB tokens_api.php:254 token_purge_expired() array (
  0 => 'DELETE FROM mantis_tokens_table WHERE 1579253948 > expiry',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=5 AND owner=764',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB bug_api.php:871 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=56810',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB bug_api.php:978 bug_text_cache_row() array (
  0 => 'SELECT bt.* FROM mantis_bug_text_table bt, mantis_bug_table b
				  WHERE b.id=56810 AND b.bug_text_id = bt.id',
  1 => '0.0009',
)
2020-01-17 10:39 CET DB category_api.php:306 category_get_row() array (
  0 => 'SELECT * FROM mantis_category_table WHERE id=523',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB project_hierarchy_api.php:167 project_hierarchy_cache() array (
  0 => 'SELECT DISTINCT p.id, ph.parent_id, p.name, p.inherit_global, ph.inherit_parent
				  FROM mantis_project_table p
				  LEFT JOIN mantis_project_hierarchy_table ph
				    ON ph.child_id = p.id
				  WHERE p.enabled = \'1\'
				  ORDER BY p.name',
  1 => '0.0015',
)
2020-01-17 10:39 CET DB version_api.php:238 version_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_project_version_table WHERE project_id IN (157,0)',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (966)',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_api.php:1730 bug_get_attachments() array (
  0 => 'SELECT id, title, diskfile, filename, filesize, file_type, date_added, user_id, bugnote_id
		                FROM mantis_bug_file_table
		                WHERE bug_id=56810
		                ORDER BY date_added',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB bugnote_api.php:611 bugnote_get_all_bugnotes() array (
  0 => 'SELECT b.*, t.note
			          	FROM      mantis_bugnote_table b
			          	LEFT JOIN mantis_bugnote_text_table t ON b.bugnote_text_id = t.id
						WHERE b.bug_id=56810
						ORDER BY b.date_submitted ASC, b.id ASC',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB relationship_api.php:444 relationship_get_all_src() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.destination_bug_id = mantis_bug_table.id
				WHERE source_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0009',
)
2020-01-17 10:39 CET DB relationship_api.php:485 relationship_get_all_dest() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.source_bug_id = mantis_bug_table.id
				WHERE destination_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0008',
)
2020-01-17 10:39 CET DB custom_field_api.php:817 custom_field_get_linked_ids() array (
  0 => 'SELECT CFP.project_id, CF.id FROM mantis_custom_field_table CF  JOIN mantis_custom_field_project_table CFP ON CFP.field_id = CF.id WHERE CFP.project_id IN (157)	ORDER BY sequence ASC, name ASC',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB tag_api.php:139 tag_cache_bug_tag_rows() array (
  0 => 'SELECT B.id AS bug_id, BT.tag_id, BT.user_id, BT.date_attached FROM mantis_bug_table B LEFT OUTER JOIN mantis_bug_tag_table BT ON B.id=BT.bug_id WHERE B.id IN (56810)',
  1 => '0.0063',
)
2020-01-17 10:39 CET DB bug_api.php:2099 bug_get_monitors() array (
  0 => 'SELECT user_id, enabled
			FROM mantis_bug_monitor_table m, mantis_user_table u
			WHERE m.bug_id=56810 AND m.user_id = u.id
			ORDER BY u.realname, u.username',
  1 => '0.0011',
)
2020-01-17 10:39 CET DB history_api.php:272 history_query_result() array (
  0 => 'SELECT * FROM mantis_bug_history_table WHERE mantis_bug_history_table.bug_id = 56810 ORDER BY mantis_bug_history_table.date_modified ASC, mantis_bug_history_table.id ASC',
  1 => '0.1308',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (430)',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (31)',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (679)',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (921)',
  1 => '0.0006',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (920)',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_api.php:871 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=59490',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (11)',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (511)',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB bug_api.php:871 bug_cache_row() array (
  0 => 'SELECT * FROM mantis_bug_table WHERE id=60920',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_api.php:1730 bug_get_attachments() array (
  0 => 'SELECT id, title, diskfile, filename, filesize, file_type, date_added, user_id, bugnote_id
		                FROM mantis_bug_file_table
		                WHERE bug_id=56810
		                ORDER BY date_added',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB user_api.php:130 user_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_user_table WHERE id IN (0)',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB user_api.php:376 user_is_monitoring_bug() array (
  0 => 'SELECT COUNT(*) FROM mantis_bug_monitor_table
				  WHERE user_id=764 AND bug_id=56810',
  1 => '0.0006',
)
2020-01-17 10:39 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB tokens_api.php:202 token_create() array (
  0 => 'INSERT INTO mantis_tokens_table
					( type, value, timestamp, expiry, owner )
					VALUES ( 3, \'56810\', 1579253990, 1579340390, 764 )',
  1 => '0.0020',
)
2020-01-17 10:39 CET DB user_api.php:1174 user_get_accessible_subprojects() array (
  0 => 'SELECT DISTINCT p.id, p.name, ph.parent_id
					  FROM mantis_project_table p
					  LEFT JOIN mantis_project_hierarchy_table ph
					    ON ph.child_id = p.id
					  WHERE p.enabled = \'1\' AND
					  	 ph.parent_id IS NOT NULL
					  ORDER BY p.name',
  1 => '0.0010',
)
2020-01-17 10:39 CET DB project_api.php:149 project_cache_array_rows() array (
  0 => 'SELECT * FROM mantis_project_table WHERE id IN (169,126,331,288,290,162,285,340,59,93,313,270,207,160,277,60,299,179,346,159,74,222,11,68,109,49,2,6,47,14,155,156,188,338,172,163,3,158,282,268,321,297,190,258,189,320,342,127,339,212,234,269,240,237,215,221,235,204,231,350,343,223,198,317,196,178,187,281,173,337,181,312,316,267,182,303,286,326,306,275,304,324,323,322,325,192,251,193,289,291,203,220,305,202,205,296,161,308,341,89,211,276,236,327,264,352,345,265,266,332,328,329,314,315,318,319,271,284,272,208,259,233,216,229,241,217,245,244,248,246,243,242,249,247,351,311,310,333,301,25,26,307,298,336,353,335,334,278,230,200,201,300,180,349,348,347,53,4,279,69,261,255,124,210,262,118,254,302,123,330,175,174,280,219,309,273,54,61)',
  1 => '0.0013',
)
2020-01-17 10:39 CET DB tokens_api.php:85 token_get() array (
  0 => 'SELECT * FROM mantis_tokens_table WHERE type=3 AND owner=764',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB access_api.php:163 access_cache_matrix_user() array (
  0 => 'SELECT project_id, access_level FROM mantis_project_user_list_table WHERE user_id=966',
  1 => '0.0018',
)
2020-01-17 10:39 CET DB project_api.php:687 project_get_all_user_rows() array (
  0 => 'SELECT id, username, realname, access_level
				FROM mantis_user_table
				WHERE enabled = 1
					AND access_level >= 90 ',
  1 => '0.0010',
)
2020-01-17 10:39 CET DB project_api.php:702 project_get_all_user_rows() array (
  0 => 'SELECT u.id, u.username, u.realname, l.access_level
				FROM mantis_project_user_list_table l, mantis_user_table u
				WHERE l.user_id = u.id
				AND u.enabled = 1
				AND l.project_id = 157',
  1 => '0.0045',
)
2020-01-17 10:39 CET DB tag_api.php:708 tag_get_candidates_for_bug() array (
  0 => 'SELECT id, name, description FROM mantis_tag_table WHERE id NOT IN (SELECT tag_id FROM mantis_bug_tag_table WHERE bug_id = 56810) ORDER BY name ASC ',
  1 => '0.0012',
)
2020-01-17 10:39 CET DB relationship_api.php:444 relationship_get_all_src() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.destination_bug_id = mantis_bug_table.id
				WHERE source_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB relationship_api.php:485 relationship_get_all_dest() array (
  0 => 'SELECT mantis_bug_relationship_table.id, mantis_bug_relationship_table.relationship_type,
				mantis_bug_relationship_table.source_bug_id, mantis_bug_relationship_table.destination_bug_id,
				mantis_bug_table.project_id
				FROM mantis_bug_relationship_table
				INNER JOIN mantis_bug_table ON mantis_bug_relationship_table.source_bug_id = mantis_bug_table.id
				WHERE destination_bug_id=56810
				ORDER BY relationship_type, mantis_bug_relationship_table.id',
  1 => '0.0005',
)
2020-01-17 10:39 CET DB access_api.php:132 access_cache_matrix_project() array (
  0 => 'SELECT user_id, access_level FROM mantis_project_user_list_table WHERE project_id=157',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_api.php:1730 bug_get_attachments() array (
  0 => 'SELECT id, title, diskfile, filename, filesize, file_type, date_added, user_id, bugnote_id
		                FROM mantis_bug_file_table
		                WHERE bug_id=56810
		                ORDER BY date_added',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB history_api.php:272 history_query_result() array (
  0 => 'SELECT * FROM mantis_bug_history_table WHERE mantis_bug_history_table.bug_id = 56810 ORDER BY mantis_bug_history_table.date_modified ASC, mantis_bug_history_table.id ASC',
  1 => '0.0033',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=49749',
  1 => '0.0019',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=49952',
  1 => '0.0027',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=51152',
  1 => '0.0012',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52371',
  1 => '0.0029',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52372',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52373',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52422',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52444',
  1 => '0.0003',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52644',
  1 => '0.0026',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52699',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=52854',
  1 => '0.0014',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53088',
  1 => '0.0028',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53426',
  1 => '0.0017',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53429',
  1 => '0.0006',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=53441',
  1 => '0.0024',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54197',
  1 => '0.0017',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54473',
  1 => '0.0012',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54609',
  1 => '0.0014',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=54783',
  1 => '0.0013',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55690',
  1 => '0.0019',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55691',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=55770',
  1 => '0.0013',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=57066',
  1 => '0.0031',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=57073',
  1 => '0.0004',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=58167',
  1 => '0.0017',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=58484',
  1 => '0.0014',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=60672',
  1 => '0.0013',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=60688',
  1 => '0.0021',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=61098',
  1 => '0.0024',
)
2020-01-17 10:39 CET DB bug_revision_api.php:84 bug_revision_exists() array (
  0 => 'SELECT id FROM mantis_bug_revision_table WHERE id=64566',
  1 => '0.0012',
)
2020-01-17 10:39 CET DB user_api.php:1489 user_update_last_visit() array (
  0 => 'UPDATE mantis_user_table SET last_visit=1579253991 WHERE id=764',
  1 => '0.0013',
)
mantis.2.23.0.log (17,345 bytes)   
dregad

dregad

2020-01-17 05:34

developer   ~0063459

the minute based timestamps are too coarse

You can customize the date format in the log by setting $g_complete_date_formatin config_inc.php.
I never realized until now that we were using this config to format logging timestamps, and TBH I'm not sure it makes sense; I think we should hardcode a more precise timestamp format, but that's a separate topic.

Looking at the times in your post, they not match those in the log files you uploaded. It could just be that the first query was executed at 10:56:59 and the second one at 10:57:00...

The only significant difference in performance that I see is with this

2020-01-17 10:45 CET DB history_api.php:272 history_query_result() array (
0 => 'SELECT * FROM mantis_bug_history_table WHERE mantis_bug_history_table.bug_id = 56810 ORDER BY mantis_bug_history_table.date_modified ASC, mantis_bug_history_table.id ASC',

Executes in 0.0032 seconds in the first log file (2.20), and 0.1308 seconds in the other (2.23), but that is not enough to explain a 30 seconds difference in page load.
tk

tk

2020-01-17 06:38

reporter   ~0063460

Maybe I found the problem.

I did the same access with full logging enabled. In the LDAP related information of the log I see in the online-tail that for each user enlisted in the bug history a (very) time-consuming request via LDAPS to the LDAP ( in my case AD ) user database is triggered. In the case given, most LDAP requests are related to the history, therefore the special locatioon of the wait time in the SQL log.
tk

tk

2020-01-17 06:46

reporter   ~0063461

Last edited: 2020-01-17 08:59

... additionally I see that each userkey is even queried each time it occurs in the list ( i.e. issue history ). All user keys that handled the issue are queried many times.

With seconds enabled I see the LDAP queries consume 39 seconds in total in my case.
tk

tk

2020-01-17 10:15

reporter   ~0063462

Last edited: 2020-01-17 10:17

Maybe the follwoing extract of the LDAP log may be of interest ( had to anonymise ) :

2020-01-17 12:42:29 CET LDAP ldap_api.php:227 ldap_get_field_from_username() Retrieving field 'displayname' for '[USERKEY]'
2020-01-17 12:42:29 CET LDAP ldap_api.php:230 ldap_get_field_from_username() Binding to LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:63 ldap_connect_bind() Attempting connection to LDAP server/URI 'ldaps://[FQDN_OF_AD/ADAM_SERVER]:636/'.
2020-01-17 12:42:29 CET LDAP ldap_api.php:66 ldap_connect_bind() Connection accepted by LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:79 ldap_connect_bind() Setting LDAP protocol version to 3
2020-01-17 12:42:29 CET LDAP ldap_api.php:101 ldap_connect_bind() Attempting bind to ldap server with username and password
2020-01-17 12:42:29 CET LDAP ldap_api.php:114 ldap_connect_bind() Bind to ldap server successful
2020-01-17 12:42:29 CET LDAP ldap_api.php:241 ldap_get_field_from_username() Searching for (&(sAMAccountName=[USERKEY]))
2020-01-17 12:42:29 CET LDAP ldap_api.php:259 ldap_get_field_from_username() Unbinding from LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:273 ldap_get_field_from_username() Found value '[RESULT: USER REAL_NAME]' for field 'displayname'.
2020-01-17 12:42:29 CET LDAP ldap_api.php:227 ldap_get_field_from_username() Retrieving field 'displayname' for '[USERKEY]'
2020-01-17 12:42:29 CET LDAP ldap_api.php:230 ldap_get_field_from_username() Binding to LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:63 ldap_connect_bind() Attempting connection to LDAP server/URI 'ldaps://[FQDN_OF_AD/ADAM_SERVER]:636/'.
2020-01-17 12:42:29 CET LDAP ldap_api.php:66 ldap_connect_bind() Connection accepted by LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:79 ldap_connect_bind() Setting LDAP protocol version to 3
2020-01-17 12:42:29 CET LDAP ldap_api.php:101 ldap_connect_bind() Attempting bind to ldap server with username and password
2020-01-17 12:42:29 CET LDAP ldap_api.php:114 ldap_connect_bind() Bind to ldap server successful
2020-01-17 12:42:29 CET LDAP ldap_api.php:241 ldap_get_field_from_username() Searching for (&(sAMAccountName=[USERKEY]))
2020-01-17 12:42:29 CET LDAP ldap_api.php:259 ldap_get_field_from_username() Unbinding from LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:273 ldap_get_field_from_username() Found value '[RESULT: USER REAL_NAME]' for field 'displayname'.
2020-01-17 12:42:29 CET LDAP ldap_api.php:227 ldap_get_field_from_username() Retrieving field 'displayname' for '[USERKEY]'
2020-01-17 12:42:29 CET LDAP ldap_api.php:230 ldap_get_field_from_username() Binding to LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:63 ldap_connect_bind() Attempting connection to LDAP server/URI 'ldaps://[FQDN_OF_AD/ADAM_SERVER]:636/'.
2020-01-17 12:42:29 CET LDAP ldap_api.php:66 ldap_connect_bind() Connection accepted by LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:79 ldap_connect_bind() Setting LDAP protocol version to 3
2020-01-17 12:42:29 CET LDAP ldap_api.php:101 ldap_connect_bind() Attempting bind to ldap server with username and password
2020-01-17 12:42:29 CET LDAP ldap_api.php:114 ldap_connect_bind() Bind to ldap server successful
2020-01-17 12:42:29 CET LDAP ldap_api.php:241 ldap_get_field_from_username() Searching for (&(sAMAccountName=[USERKEY]))
2020-01-17 12:42:29 CET LDAP ldap_api.php:259 ldap_get_field_from_username() Unbinding from LDAP server
2020-01-17 12:42:29 CET LDAP ldap_api.php:273 ldap_get_field_from_username() Found value '[RESULT: USER REAL_NAME]' for field 'displayname'.
... here we start again, in this case [USERKEY] is identical to above ...
2020-01-17 12:42:29 CET LDAP ldap_api.php:227 ldap_get_field_from_username() Retrieving field 'displayname' for '[USERKEY]'
2020-01-17 12:42:29 CET LDAP ldap_api.php:230 ldap_get_field_from_username() Binding to LDAP server

... repeating for all 400 entries in the history list ( by view, haven't counted exactly )
dregad

dregad

2020-01-17 10:48

developer   ~0063463

Thanks for the research. So if I interpret your log correctly, it seems that we're querying 3 times for the same user's realname ?

I'm not sure off-and why we're querying LDAP to begin with, and even worse, 3 times for the sameuser... I need to check further, also to dertermine what / why that changed between 2.20 and 2.23, however it might prove difficult as I don't have any LDAP or ADFS setup available for testing.
atrol

atrol

2020-01-17 11:07

developer   ~0063464

@dregad, not sure you are aware that there is $g_ldap_simulation_file_path
atrol

atrol

2020-01-18 11:42

developer   ~0063468

Last edited: 2020-01-18 18:34

I wanted to recommend setting $g_history_default_visible = OFF as a temporary workaround, but there is another regression in 2.23.0 0026610 (will be fixed in 2.23.1)
tk

tk

2020-01-20 01:50

reporter   ~0063475

Following your hint I've (temporarily) disabled history display.
This helps in parts. I also have issues with many notes -- as it seems, display of the notes triggers those many uncached LDAP queries as well.
atrol

atrol

2020-01-20 03:58

developer   ~0063477

Another temporary workaround could be to set$g_use_ldap_realname = OFF;
tk

tk

2020-01-20 04:11

reporter   ~0063478

Regrettably thats no option on my side since users wouldn't accept this, in difference to missing history.

I'm about and install a plain mantis 2.22.1 release in order reduce the amount of potential problematic changes. Or is this no help for you?
tk

tk

2020-01-20 04:18

reporter   ~0063479

Problem not present in 2.22.1
tk

tk

2020-01-20 04:29

reporter   ~0063480

since I was on the way: 2.22.2 doesn't show the problem, either
atrol

atrol

2020-01-20 05:31

developer   ~0063481

Thanks @tk for looking at this.
I don't think there is need for further investigation from your side.

From what I see, the issue is caused by this change https://github.com/mantisbt/mantisbt/commit/b90cc957fd9b0d3f38679918c424a459628a35ae
atrol

atrol

2020-01-20 07:23

developer   ~0063483

@vboctor could you have a look at this ?
tk

tk

2020-01-22 02:00

reporter   ~0063488

Hi, do you think that this regression can be solved in near future or will this take some time?

In case of the latter I have to consider downgrade of my installations to, say, 2.22.2. However I'm somewhat concerned considering the schema update executed with the upgrade to 2.23.0. Can 2.22.2 safely operate on a mysql-DB with the new schema 210? ( A rollback of my database to the state I saved at the upgrade isn't possible.)
dregad

dregad

2020-01-23 12:06

developer   ~0063502

@tk I had some free time today, and I made some improvements to LDAP API (implemented caching, see 0026622) which I believe should address the problem you reported.

Since I don't have a real-life environment I can use for testing, it would be great if you could test this on your side and let me know the results.

You will find the code to test at https://github.com/mantisbt/mantisbt/pull/1614
tk

tk

2020-01-24 02:54

reporter   ~0063508

@dregard
Good news -- I've copied the core/ldap_api.php from this branch to my mantis/2.23.0 debug installation. With this setting I don't see the performance problems any more.
Would it be feasible to use the modified ldap_api.php in my production environment or does this need additional work?
dregad

dregad

2020-01-24 04:50

developer   ~0063509

@tk Thanks for the feedback and confirming that the patch fixes the issue.

Would it be feasible to use the modified ldap_api.php in my production environment

Patching an official release is always at your own risk, but considering that this is pretty much a standalone change and there have been no other modifications to LDAP API since 2.23.0, I do not expect any adverse effects if you use the file from master branch in your installation - other than a bug introduced by the change I made, which is always possible of course.

We're planning to release 2.23.1 (including this fix) soon anyway, if you prefer to wait for an official release.
tk

tk

2020-01-24 06:38

reporter   ~0063511

Fine.

I'll start using the new ldap_api.php in my testing / preprod environment for some days. In case of problems I'll report those, so we have some deeper testing before the next official release.
tk

tk

2020-01-28 05:30

reporter   ~0063526

As a feedback, until now everything works fine, I don't see negative side effects.
I've deployed the patch in production environment.

Related Changesets

MantisBT: master b90cc957

2019-06-02 23:23

vboctor


Details Diff		 Use standard REST issue + issue view extra info Affected Issues
0026125, 0026600
mod - bug_view_inc.php Diff File
mod - core/commands/IssueViewCommand.php Diff File

MantisBT: master-2.23 709fb78e

2020-01-23 06:32

dregad


Details Diff		 Reduce number of LDAP searches

Prior to this, retrieving user information required 1 LDAP search each
time a user was referenced on a page (possibly 2 if Mantis is configured
to show the realname). This could have a significant performance impact
when displaying pages containing a large number of users (e.g. viewing
an Issue having a long history, as described in issue 0026600).

Implement a new ldap_cache_user_data() function to retrieve all needed
LDAP attributes in a single search, and cache them.

This way, we only need to query the LDAP server once per user,
subsequent calls only need to access the cache which drastically
improves performance.

Fixes 0026622, 0026600		 Affected Issues
0026600, 0026622
mod - core/ldap_api.php Diff File