Very Slow 7.7.8

SuiteCRM Forum - English Language Installation & Upgrade Help
#1

Hi.

So since we upgraded months ago from 7.4.3 to 7.7 our CRM Seems to be getting slower.

it can now take up to 15 seconds to just log into the CRM in the first place, and going into Meetings takes 5 to 10 seconds to open the page, Accounts can be longer. we have less than 50,000 accounts on the system and under 5,000 meetings but it’s just all so slow.

It’s on an onsite Virtual VM, With enough memory 26GB and doesn’t show it using any swap, 2 virtual CPU’s with 8 cores between them, and shows no issues with using more than around 20% CPU.

It’s running on Linux OpenSuse, but just seems to be getting slower all the time.

I’ve read through some stuff and it doesn’t have Developer mode enabled, as i’ve read that slows it down but it’s not that.
I’ve read there was some stuff about hidden reminders causing some systems to go slow? How would we be able to test if we had that as an issue?

Anyone else with any other ideas on what we can do. Is there a safe way to purge all deleted account from the system? So all accounts / tasks etc… with deleted = 1, or should this be done by the system automatically with the purge option in the scheduler, which is activated to run each month.

Thanks

#2

It takes 18-20 seconds between clicking on accounts and it showing the first page of 50 accounts.

#3

You can look at your logs (suitecrm.log, php_errors.log) to see if you find something suspicious.

You can also run phpMyAdmin on your database and have a look at the reminders table, and in general check the size of tables to see if anything looks suspiciously huge.

#4

Hi.

Here are the top tables. So I guess I need to look at email addresses? As that seems weird that it’s so large. I don’t know anything about SQL it’s very much just hunting through the net to try to find things to help.

±---------------------------------------±--------+
| Table | Size MB |
±---------------------------------------±--------+
| email_addresses | 757.98 |
| email_addr_bean_rel | 446.83 |
| accounts | 435.63 |
| user_activity | 359.97 |
| aod_indexevent | 194.39 |
| aow_processed | 193.98 |
| job_queue | 156.73 |
| aow_processed_aow_actions | 144.77 |
| aos_products | 86.27 |
| accounts_audit | 61.28 |
| accounts_cstm | 58.73 |
| securitygroups_records | 49.63 |

#5

The total database is around 3GB, 3117MB

#6

Only you can have the perception of whether those sizes are normal or not, according to your data and your use.

Try browsing through those tables and see what’s in there, if it makes sense to you, or if you see a huge number of records with deleted=1, or repeated, or for some reason stale.

I would also look at aod_indexevent and try to figure out if you have a problem with indexing (are your Scheduler jobs running with success? Specifically, “Perform Lucene Index” and “Optimise AOD Index”)

The logs would help you get a more dynamic view of this. What is your system doing to make it slow? Is it reporting errors to point you in a more definite direction?

#7

Hi.

I had a look at the scheduler and the only weird thing is that the monthly prune wasn’t enabled. So i’ve just enabled it and tried running it.

Tue Mar 14 10:31:08 2017 [15472][1][FATAL] Job dfe001e3-6a75-43d0-fdfb-58c7c663ebc1 (Prune Database on 1st of Month) failed in CRON run

#8

Check out my guide here:
https://suitecrm.com/forum/installation-upgrade-help/12385-guide-how-to-speed-up-your-crm-get-a-better-response-time#42058

It may help!
It also wouldn’t hurt to try and a quick repair once in a while

#9

@booktrunk that guide is actually very good (thanks OIiver!)), but I wouldn’t advise going for generic performance tweaks until you are sure you don’t have a specific problem that simply needs fixing. And it seems you do. You have to work your way out of errors in the logs.

If you increase log level a bit, do you get any extra insight about that cron job failure? What do you have in php_errors.log at the same time?

#10

Hi.

I’m struggling to find my php log. I’m not sure if it is enabled. I’m just looking in /etc/php5/apache2/php.ini and I think I need to enable the php log in there. As it doesn’t seem to have one.

#11

OK. Being Dense it’s putting the php in the apache error log.

#12

We have a test CRM with is basically a copy of the live CRM from a couple of months ago.

We tweaked some things in live and some in test and not kept an exact log of the changes, but there are essentially the same amount of data in both accounts with 50M in the 3GB database.

The live server has 8 cores and around 26gb of memory.
The test server has 2 cores and 8gb of memory.

When we click on the Accounts module to list the accounts there are actually 3,000 extra records in the test server as opposed to the live server, but the test server takes around 4 seconds to show a list of the first 50 of the accounts in test and around 20 seconds in live.

So really it’s just looking through the apache log / error log and suitecrm log to see if there is anything in them, and if it doesn’t show much look at increasing the log levels within apache?

#13

10.100.100.110 - - [14/Mar/2017:12:43:27 +0000] “GET /index.php?module=Alerts&action=get&to_pdf=1 HTTP/1.1” 200 46 “http://..com/index.php?action=ajaxui” “Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:51.0) Gecko/20100101 Firefox/51.0”
10.100.100.110 - - [14/Mar/2017:12:43:23 +0000] “GET /index.php?module=Accounts&action=index&parentTab=Sales&ajax_load=1 HTTP/1.1” 200 34153 “http://..com/index.php?action=ajaxui” “Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:51.0) Gecko/20100101 Firefox/51.0”

So that was the request to look at the file going through Apache.

There was 0 assoicated with this in the apache error log.

Going through and listing the accounts as I say is a lot slower on the live as opposed to the test account. But it’s not generating any errors that i can see in /var/log/apache2/apache_log and errors_log, we do get errors when users are doing certain things so we need to look at them but i don’t think they are causing these issues.

#14

You can increase the log level in suitecrm.log (on Admin, System Settings). You will get tons of messages, most of them don’t mean anything, so don’t get lost, just focus on what you’re currently trying to solve.

When I asked about the php_errors.log, it was related to the cron job failure while pruning the database. I have a hunch that might give us clues. At least, it’s a single event that we can focus on.

1 Like
#15

Here is the error log.

Tue Mar 14 14:19:02 2017 [16124][1][INFO] ----->Scheduler fired job of type pruneDatabase()
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query:SHOW TABLES
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query Execution Time:0.0010240077972412
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query:DESCRIBE accounts
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query Execution Time:0.00059413909912109
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query:DESCRIBE accounts_cstm
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query Execution Time:0.00074601173400879
Tue Mar 14 14:19:02 2017 [16124][1][INFO] Query:SELECT * FROM accounts WHERE deleted = 1
Tue Mar 14 14:19:10 2017 [16124][1][FATAL] Job 24309cc9-8564-2caa-7cf3-58c7fbc50e49 (Prune Database on 1st of Month) failed in CRON run
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Resolving job 24309cc9-8564-2caa-7cf3-58c7fbc50e49 as failure: Unexpected failure, please check PHP logs and suitecrm.log
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id=‘1’ AND category = ‘global’ AND deleted = 0
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query Execution Time:0.0006101131439209
Tue Mar 14 14:19:10 2017 [16124][1][DEPRECATED] Formatting correction: SchedulersJobs->failure_count had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 14:19:10 2017 [16124][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Prune Database on 1st of Month’,date_modified=‘2017-03-14 14:19:01’,scheduler_id=‘37066481-bc11-f659-9775-57b6e5da6c25’,execute_time=‘2017-03-14 14:19:00’,status=‘done’,resolution=‘failure’,message=‘Unexpected failure, please check PHP logs and suitecrm.log\n’,target=‘function::pruneDatabase’,data=NULL,requeue=0,retry_count=NULL,failure_count=1,job_delay=0,client=‘CRON70785c528a9795a536968c27febffdc7:16124’,percent_complete=NULL

Just trying to hunt through to find some php logs
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query Execution Time:0.0092809200286865
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query Execution Time:0.0010230541229248
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 14:19:10 2017 [16124][1][INFO] Query Execution Time:0.00037503242492676

#16

So I have setup the php log to go to a separate file.

/var/log/php-scripts.log

Nothing… I ran the prune job again at 2:45PM and the log file in suitecrm showed pretty much the same thing. But there was nothing in the php-scripts.log

So 0 php logs.

#17

Maybe you’re changing the wrong php.ini.

You should have two of those, on my system they are

/etc/php/7.0/apache2/php.ini
/etc/php/7.0/cli/php.ini

The first applies to the web apps, the second to the CLI. Since cron jobs (normally) run from the command-line, the CLI file will be used.

#18

Hi.

Sorry I had done apache2 but not cli. So i’ve now done it in CLI as well. That looks good now:-
php --info | grep error
display_errors => Off => Off
display_startup_errors => Off => Off
error_append_string => no value => no value
error_log => /var/log-php-scripts.log => /var/log-php-scripts.log
error_prepend_string => no value => no value
error_reporting => 22527 => 22527
html_errors => Off => Off
ignore_repeated_errors => Off => Off
log_errors => On => On
log_errors_max_len => 1024 => 1024
track_errors => Off => Off
xmlrpc_error_number => 0 => 0
xmlrpc_errors => Off => Off
intl.error_level => 0 => 0
mssql.min_error_severity => 10 => 10
suhosin.disable.display_errors => Off => Off
suhosin.sql.bailout_on_error => Off => Off
opcache.error_log => no value => no value

Trying again :slight_smile: watch this space.

#19

OK The only thing I can see in the php directory is an LDAP Error that is coming up each and every minute more of a strict standards warning message
[14-Mar-2017 15:36:06 UTC] PHP Strict Standards: Declaration of SugarEmailAddress::save() should be compatible with SugarBean::save($check_notify = false) in /srv/www/htdocs/include/SugarEmailAddress/SugarEmailAddress.php on line 0
[14-Mar-2017 15:36:06 UTC] PHP Strict Standards: Declaration of LDAPAuthenticateUser::authenticateUser() should be compatible with SugarAuthenticateUser::authenticateUser($name, $password, $fallback = false) in /srv/www/htdocs/modules/Users/authentication/LDAPAuthenticate/LDAPAuthenticateUser.php on line 52

BUT this i’m sure is a red herring as it comes up every single minute if not twice a minute it’s not related i’m sure. So nothing in the PHP log?

Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found language file: en_us.lang.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found extended language file: en_us.lang.ext.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found custom language file: en_us.lang.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = ‘Active’ and deleted = 0
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query Execution Time:0.00032806396484375
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query:SELECT category, name, value FROM config
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query Execution Time:0.00028896331787109
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = ‘system’
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query Execution Time:0.00017499923706055
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = ‘e9c81514-cffb-3988-262e-5630c1132f95’
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query Execution Time:0.00018000602722168
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found language file: en_us.lang.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found extended language file: en_us.lang.ext.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Found custom language file: en_us.lang.php
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][-none-][INFO] Query Execution Time:0.00031590461730957
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id=‘1’ AND category = ‘global’ AND deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00026702880859375
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id, first_name, last_name, user_name FROM users WHERE 1=1 ORDER BY first_name, last_name ASC
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00037002563476562
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00017309188842773
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00059103965759277
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM job_queue WHERE status=‘running’ AND date_modified <= ‘2017-03-13 15:35:01’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00026392936706543
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query: SELECT schedulers.* , jt0.user_name created_by_name , jt0.created_by created_by_name_owner , ‘Users’ created_by_name_mod , jt1.user_name modified_by_name , jt1.created_by modified_by_name_owner , ‘Users’ modified_by_name_mod FROM schedulers LEFT JOIN users jt0 ON jt0.id=schedulers.created_by AND jt0.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00074315071105957
Tue Mar 14 15:35:01 2017 [2433][1][INFO] -----> Scheduler found [ 13 ] ACTIVE jobs
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00023102760314941
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00022411346435547
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00016379356384277
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00035810470581055
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0001530647277832
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0001988410949707
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00015497207641602
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00029182434082031
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:INSERT INTO job_queue (assigned_user_id,id,name,deleted,date_entered,date_modified,scheduler_id,execute_time,status,resolution,target,requeue,job_delay,client)
VALUES (‘1’,‘4a463e75-2a2f-2272-a7ce-58c80d26a6d7’,‘Process Workflow Tasks’,0,‘2017-03-14 15:35:01’,‘2017-03-14 15:35:01’,‘303c73c1-1e89-4616-eb47-57b6e57e14b5’,‘2017-03-14 15:35:01’,‘queued’,‘queued’,‘function::processAOW_Workflow’,0,0,’’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0011510848999023
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00052714347839355
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004429817199707
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00049591064453125
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043678283691406
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT aod_index.* FROM aod_index WHERE aod_index.id = ‘1’ AND aod_index.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00032615661621094
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00023603439331055
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00020313262939453
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00024104118347168
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00016903877258301
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00032901763916016
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:INSERT INTO job_queue (assigned_user_id,id,name,deleted,date_entered,date_modified,scheduler_id,execute_time,status,resolution,target,requeue,job_delay,client)
VALUES (‘1’,‘537c899d-d9f1-96de-a0b0-58c80d6f9d2c’,‘Run Report Generation Scheduled Tasks’,0,‘2017-03-14 15:35:01’,‘2017-03-14 15:35:01’,‘320bb59e-7d95-82ee-3a65-57b6e5d65f30’,‘2017-03-14 15:35:01’,‘queued’,‘queued’,‘function::aorRunScheduledReports’,0,0,’’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00087809562683105
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00049781799316406
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00044894218444824
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043320655822754
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004270076751709
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00018906593322754
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00016498565673828
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0002131462097168
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00015711784362793
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00030612945556641
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:INSERT INTO job_queue (assigned_user_id,id,name,deleted,date_entered,date_modified,scheduler_id,execute_time,status,resolution,target,requeue,job_delay,client)
VALUES (‘1’,‘5644be14-1758-956a-cd4b-58c80d4ebb27’,‘Check Inbound Mailboxes’,0,‘2017-03-14 15:35:01’,‘2017-03-14 15:35:01’,‘34097565-d5f9-7be6-1ae7-57b6e51edfd0’,‘2017-03-14 15:35:01’,‘queued’,‘queued’,‘function::pollMonitoredInboxesAOP’,0,0,’’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00069093704223633
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004580020904541
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043010711669922
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043702125549316
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004270076751709
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00019598007202148
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00017714500427246
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00020408630371094
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00017499923706055
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00028896331787109
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:INSERT INTO job_queue (assigned_user_id,id,name,deleted,date_entered,date_modified,scheduler_id,execute_time,status,resolution,target,requeue,job_delay,client)
VALUES (‘1’,‘585d8ea2-7931-16c4-988f-58c80dc2e132’,‘Prune Database on 1st of Month’,0,‘2017-03-14 15:35:01’,‘2017-03-14 15:35:01’,‘37066481-bc11-f659-9775-57b6e5da6c25’,‘2017-03-14 15:35:01’,‘queued’,‘queued’,‘function::pruneDatabase’,0,0,’’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00075912475585938
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00044894218444824
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043106079101562
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004270076751709
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00042891502380371
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00018095970153809
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM users WHERE id = ‘1’ AND is_admin = 1 AND deleted = 0 AND status = ‘Active’ LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00015091896057129
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00020694732666016
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00015616416931152
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00027680397033691
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:INSERT INTO job_queue (assigned_user_id,id,name,deleted,date_entered,date_modified,scheduler_id,execute_time,status,resolution,target,requeue,job_delay,client)
VALUES (‘1’,‘5b1f6b26-9907-9e4d-2b5e-58c80d11fd2b’,‘Run Email Reminder Notifications’,0,‘2017-03-14 15:35:01’,‘2017-03-14 15:35:01’,‘3a3c05ed-2942-238d-5e96-57b6e54b6eeb’,‘2017-03-14 15:35:01’,‘queued’,‘queued’,‘function::sendEmailReminders’,0,0,’’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00079703330993652
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00047802925109863
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043702125549316
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043106079101562
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00042510032653809
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0002140998840332
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= ‘2017-03-14 15:35:01’ AND status = ‘queued’ ORDER BY date_entered ASC|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= ‘2017-03-14 15:35:01’ AND status = ‘queued’ ORDER BY date_entered ASC LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00029301643371582
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘5b1f6b26-9907-9e4d-2b5e-58c80d11fd2b’ AND job_queue.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00016999244689941
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE job_queue SET status=‘running’, date_modified=‘2017-03-14 15:35:01’, client=‘CRON70785c528a9795a536968c27febffdc7:2433’ WHERE id=‘5b1f6b26-9907-9e4d-2b5e-58c80d11fd2b’ AND status=‘queued’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00085115432739258
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->date_entered had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->date_modified had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->execute_time had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Run Email Reminder Notifications’,date_modified=‘2017-03-14 15:35:01’,scheduler_id=‘3a3c05ed-2942-238d-5e96-57b6e54b6eeb’,execute_time=‘2017-03-14 15:35:00’,status=‘running’,resolution=‘queued’,message=NULL,target=‘function::sendEmailReminders’,data=NULL,requeue=0,retry_count=NULL,failure_count=NULL,job_delay=0,client=‘CRON70785c528a9795a536968c27febffdc7:2433’,percent_complete=NULL
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00080204010009766
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043988227844238
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00019502639770508
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT users.,users_cstm. FROM users LEFT JOIN users_cstm ON users.id = users_cstm.id_c WHERE users.id = ‘1’ AND users.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00026822090148926
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT u1.first_name, u1.last_name from users u1, users u2 where u1.id = u2.reports_to_id AND u2.id = ‘1’ and u1.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00016498565673828
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT ea.email_address, ea.email_address_caps, ea.invalid_email, ea.opt_out, ea.date_created, ea.date_modified,
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00032591819763184
Tue Mar 14 15:35:01 2017 [2433][1][INFO] ----->Scheduler fired job of type sendEmailReminders()
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query: SELECT reminders.* , jt0.user_name modified_by_name , jt0.created_by modified_by_name_owner , ‘Users’ modified_by_name_mod , jt1.user_name created_by_name , jt1.created_by created_by_name_owner , ‘Users’ created_by_name_mod , jt2.user_name assigned_user_name , jt2.created_by assigned_user_name_owner , ‘Users’ assigned_user_name_mod FROM reminders LEFT JOIN users jt0 ON reminders.modified_user_id=jt0.id AND jt0.deleted=0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00075888633728027
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:
AND date_start >= ‘2017-03-14 15:35:01’
AND date_start <= ‘2017-03-15 15:35:01’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00023603439331055
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:
AND date_start >= ‘2017-03-14 15:35:01’
AND date_start <= ‘2017-03-15 15:35:01’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00026202201843262
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Resolving job 5b1f6b26-9907-9e4d-2b5e-58c80d11fd2b as success:
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Run Email Reminder Notifications’,date_modified=‘2017-03-14 15:35:01’,scheduler_id=‘3a3c05ed-2942-238d-5e96-57b6e54b6eeb’,execute_time=‘2017-03-14 15:35:00’,status=‘done’,resolution=‘success’,message=NULL,target=‘function::sendEmailReminders’,data=NULL,requeue=0,retry_count=NULL,failure_count=NULL,job_delay=0,client=‘CRON70785c528a9795a536968c27febffdc7:2433’,percent_complete=NULL
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00089287757873535
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0004730224609375
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00018692016601562
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE schedulers SET last_run=‘2017-03-14 15:35:01’ WHERE id=‘3a3c05ed-2942-238d-5e96-57b6e54b6eeb’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00068902969360352
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= ‘2017-03-14 15:35:01’ AND status = ‘queued’ ORDER BY date_entered ASC|
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= ‘2017-03-14 15:35:01’ AND status = ‘queued’ ORDER BY date_entered ASC LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00024795532226562
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘585d8ea2-7931-16c4-988f-58c80dc2e132’ AND job_queue.deleted=0 LIMIT 0,1
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00019001960754395
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE job_queue SET status=‘running’, date_modified=‘2017-03-14 15:35:01’, client=‘CRON70785c528a9795a536968c27febffdc7:2433’ WHERE id=‘585d8ea2-7931-16c4-988f-58c80dc2e132’ AND status=‘queued’
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00070905685424805
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->date_entered had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->date_modified had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->execute_time had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:01 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Prune Database on 1st of Month’,date_modified=‘2017-03-14 15:35:01’,scheduler_id=‘37066481-bc11-f659-9775-57b6e5da6c25’,execute_time=‘2017-03-14 15:35:00’,status=‘running’,resolution=‘queued’,message=NULL,target=‘function::pruneDatabase’,data=NULL,requeue=0,retry_count=NULL,failure_count=NULL,job_delay=0,client=‘CRON70785c528a9795a536968c27febffdc7:2433’,percent_complete=NULL
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0032551288604736
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00043606758117676
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00018095970153809
Tue Mar 14 15:35:01 2017 [2433][1][INFO] ----->Scheduler fired job of type pruneDatabase()
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SHOW TABLES
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.0010130405426025
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:DESCRIBE accounts
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00059103965759277
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:DESCRIBE accounts_cstm
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query Execution Time:0.00073909759521484
Tue Mar 14 15:35:01 2017 [2433][1][INFO] Query:SELECT * FROM accounts WHERE deleted = 1
Tue Mar 14 15:35:16 2017 [2433][1][FATAL] Job 585d8ea2-7931-16c4-988f-58c80dc2e132 (Prune Database on 1st of Month) failed in CRON run
Tue Mar 14 15:35:16 2017 [2433][1][INFO] Resolving job 585d8ea2-7931-16c4-988f-58c80dc2e132 as failure: Unexpected failure, please check PHP logs and suitecrm.log
Tue Mar 14 15:35:16 2017 [2433][1][INFO] Query:SELECT contents FROM user_preferences WHERE assigned_user_id=‘1’ AND category = ‘global’ AND deleted = 0
Tue Mar 14 15:35:16 2017 [2433][1][INFO] Query Execution Time:0.00063514709472656
Tue Mar 14 15:35:16 2017 [2433][1][DEPRECATED] Formatting correction: SchedulersJobs->failure_count had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Tue Mar 14 15:35:16 2017 [2433][1][DEPRECATED] SugarBean.php: preprocess_fields_on_save() is deprecated
Tue Mar 14 15:35:16 2017 [2433][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Prune Database on 1st of Month’,date_modified=‘2017-03-14 15:35:01’,scheduler_id=‘37066481-bc11-f659-9775-57b6e5da6c25’,execute_time=‘2017-03-14 15:35:00’,status=‘done’,resolution=‘failure’,message=‘Unexpected failure, please check PHP logs and suitecrm.log\n’,target=‘function::pruneDatabase’,data=NULL,requeue=0,retry_count=NULL,failure_count=1,job_delay=0,client=‘CRON70785c528a9795a536968c27febffdc7:2433’,percent_complete=NULL
Tue Mar 14 15:35:16 2017 [2433][1][INFO] Query Execution Time:0.001924991607666

#20

I wonder if it’s beaking in this query:
SELECT * FROM accounts WHERE deleted = 1

It starts, takes 15 seconds, then before giving the query time it fails with a fatal error.

You could try…

  1. See how the same thing looks on the logs of your faster system;

  2. Running that query from phpMyAdmin to see if any error (or long delay) comes up in MySQL.