SC calling MySQLi::disconnect every iteration in PHP for loop?

Hi all,
I’m running a PHP script that imports 2,795 accounts from an iSeries. If an account exists, I update it, and if it doesn’t, I create it. In either case, the process is basically:

for each row in query_results:
create/update the user account, save that bean
create/update the account in the row, save, relate it to the user above
create/update two contacts for this account, both stored in $row, save each, relate it to the account

I’m seeing something odd though. My log (with level set to debug) shows a long stretch of time between two lines. I have to break up my results, or even after twenty minutes, my script will time out, and I think I found the reason. Here are two lines, which appear sequentially in my log:

Thu Nov 16 17:12:08 2017 [15216][15ff1805-eee4-49fd-64c2-5a0c678a1e7c][DEBUG] Calling MySQLi::disconnect()
Thu Nov 16 17:12:47 2017 [15219][-none-][DEBUG] current_language is: en_us

Nothing happens in that 39-second window. Why, though, does it disconnect, then seem to restart the entire connection process? Can I keep it alive instead? Any ideas on what might be going on would be great. Thanks!

  1. Do you see any errors in php_errors.log?

  2. Are yo connecting to your database locally or remotely? If remotely, maybe look into network issues, latency, DNS. If locally, make sure you use ‘localhost’ to reference your server, not ‘127.0.0.1’.

Thanks for the reply. My php5-fpm.log file shows only the times my script exceeded the maximum timeout and exited. Other than the warnings about workers exiting and the script stopping, I have nothing. When my script stays below max execution time, the log has no messages.

I’m using localhost. SQL query times aren’t a problem–most execute in under a tenth of a second–it seems something in how SC works is to blame. From what I can tell, which isn’t much, SC saves a bean and closes the connection to MySQL (MySQLI::disconnect). Then, for whatever reason, SC starts up again, going through cache checks, querying for metadata and other information, etc. From when this process begins to the next MySQLi::disconnect() call is less than a second, but then there’s that pause of up to 40 or more seconds before the next burst of activity. This pattern is repeated over and over again, with each burst taking under a second but each pause taking many times longer. I can’t tell that’s happening during these pauses since the log shows nothing at all, which is how I know said pauses are happening.

A generic advice: if you can install XDEBUG and get a proper IDE and debugger working with SuiteCRM, your development experience will improve 500%.

About this specific thing, it just occurred to me… Do you happen to have “Developer mode” turned on in Admin / System Settings? If so, try turning it off.

Good thought about XDebug. I’ve never used that before, so installed it and will look more into it.

I did have developer mode enabled, so turned that off; that didn’t seem to make a difference in execution time, unfortunately.

The only place I found in all of SC’s code where the disconnect function is called is in modules/administration/locale.php. I don’t understand in the slighted what is happening here, what collation has to do with anything, or what I might try to stop this. But there’s a call to disconnect(), followed immediately by a call to connect(), so I have to wonder if this is where my problem lies. I’d comment it out just to see what it does, but I don’t like the idea of removing bits of code I don’t understand. Who knows what might happen as a result, especially if I forget and leave it off when we enter production? Anyway, here’s the code I’m talking about from locale.php:

if(isset($_REQUEST[‘process’]) && $_REQUEST[‘process’] == ‘true’) {
if(isset($_REQUEST[‘collation’]) && !empty($_REQUEST[‘collation’])) {
//kbrill Bug #14922
if(array_key_exists(‘collation’, $sugar_config[‘dbconfigoption’]) && $_REQUEST[‘collation’] != $sugar_config[‘dbconfigoption’][‘collation’]) {
$GLOBALS[‘db’]->disconnect();
$GLOBALS[‘db’]->connect();
}

	$cfg->config['dbconfigoption']['collation'] = $_REQUEST['collation'];
}
$cfg->populateFromPost();
$cfg->handleOverride();
if ($locale->invalidLocaleNameFormatUpgrade()) {
    $locale->removeInvalidLocaleNameFormatUpgradeNotice();
}
header('Location: index.php?module=Administration&action=index');

}

You shouldn’t have t change code, it should really work, there must be some small detail in your configuration breaking things.

Anyway, debugging will let you get a much better grasp of where the problem is and it will probably bring you clues.

Another idea I have is to play with MySQL timeouts (or PHP modules that access MYSQL) if you find any in the configuration times, since they might explain the delays.

You can also check syslog to see if your system is showing any networking events, for example.

Those are the ideas I could think of at the moment…

Hello,
I can’t get xdebug to work for some reason, but I’ll keep trying. I was hoping to profile my script.

What I can say, though, is that I’ve tried a few other things and I keep coming back to this, somehow, being SC’s fault. Every time there’s a long delay in the log, it’s right after a call to MySQLi::disconnect(). However, there isn’t always a delay after such a call, just a call before each delay. What I’ve tried/thought of:

  • I have Request Tracker (www.bestpractical.com) running on the same server and using the same MySQL instance. There are no slow-downs in that program like there are here, so I don’t think the server is the problem.

  • I’ve double checked, and max_question, max_connections, and the other columns I could think of that control whether a user is locked out are all 0.

  • I looked at syslog, but all I find are the messages each minute indicating that SC’s cron job ran. That file is empty, so nothing is happening there.

  • I found a setting in config.php called “db_host_instance”, set to “SQLEXPRESS”. I changed it to "MYSQL just to see what it would do, but it made no difference.

Any other ideas or suggestions would be wonderful. The importing of even a few contacts is far too long to make this worth while as things stand. If and when I get xdebug to work, I’ll update with anything useful I find from there.

I am a bit lost so all I can give you are generic suggestions for your investigation:

  1. Try to use “top” to check CPU action during the delays. Does it spike during the delay, like some program is going around in a loop?

  2. Try to use “iotop” (or your eyes looking at the disk light) to check disk usage during the delay. Does it spike, like the disk is busy working through something?

  3. I don’t know the best tool, but try to profile network activity during the delay. I would say this is the most likely culprit, because constant delays that are 20 or 30 or 60 seconds long are typically network timeouts of some sort. A bad DNS config somewhere, a corrupt cache, etc.

  4. Try to escape the problem altogether by changing your system’s config. Mode to a different Linux, to a different Web server, upgrade versions, reinstall. I’ve never seen anyone have your problem with SuiteCRM, so while I can’t rule out it’s a SuiteCRM bug, it sure looks like something in the stack is at least acting unusually.

Good luck, I’ll come back if I think of more ideas for you to try…

Well, Xdebug is working, as is WinCacheGrind. But it makes no sense! The largest thing I see here is SugarBean->save, which took a total of 16.417 seconds for twenty calls. I’ve looked for anything else related, though, and found nothing. Connect and disconnect each have just one call, not the multiple ones the logs show, and take no time at all. Either I’m looking at the wrong file, or this just got even weirder.

Is there sensitive information in the Xdebug profiler output? If not, I’m happy to upload a file here for others to browse. Maybe someone is experienced with reading these and will see something I’m missing.

I never used XDEBUG profiling. When I suggested XDEBUG I was thinking of it simply as a debugging tool, to really determine where the slow call is taking place, and to contrast the values of arguments in that call with other times when the call completes quickly.

Of course, using profiling for this also makes sense, but I can’t help you through it, I just don’t know how it works… for example, I’m not sure how it handles delays in the functions that are called by the PHP code, but are not part of the PHP code - like MySQL. Maybe it just ignores them.

I’m setting it up now. I’m new to all this, so chose Eclipse to run as my IDE. I’ve configured the xdebug.remote_* variables on the SuiteCRM server, I think, and have opened my custom PHP file in Eclipse. But how do I get it to run? Most of the time, the URL would simply be http://crm.example.com/customFile.php. But with entry points, the URL is very different. Is there anything I need to do in Eclipse to make sure this all goes right?

Make sure you have opened firewall ports for the XDEBUG port (usually 9000).

You need to get the debugger to attach to the process you’re debugging.

This can happen in two ways:

  • it’s already running, but you set a breakpoint and code execution stops at a given file

  • you set up a start page in Eclipse (like index.html), and order it ti start debugging. It will launch the page on the brwoser and attach to the code.

That said, it’s hard to get it working. I had loads of problems with Eclipse and XDEBUG. You need to find your way around blog posts and tutorials. I’m not using it anymore, so it’s hard for me to help. But once it’s working, it’s extremely rewarding for productivity.

I never did get Xdebug to work, so I took the poor man’s debugging route. I put “$var = new DateTime()” declarations all over the place, and echoed the end minus start times. Here’s the result. It seems like searching for existing data is fast, but saving it is slow. Some contact or account bean updates take four or more seconds, and saving a relationship takes as long or longer. Yet searching never takes any significant time at all. Does this help pinpoint anything?

User account for [username] already exists.
User import completed in 0:0:0
New account bean gotten in 0:0:0
Account search took 0:0:0
Found account for [account_name]. Updating it.
Account imported in 0:0:1
Account relationship added in 0:0:0
purchasing contact for [account_name] exists. Updating it.
Contact imported in 0:0:0
Contact relationship saved in 0:0:0
accounts payable contact for [account_name] exists. Updating it.
Contact imported in 0:0:2
Contact relationship saved in 0:0:0

User account for [username] already exists.
User import completed in 0:0:0
New account bean gotten in 0:0:0
Account search took 0:0:0
Found account for [account_name_2]. Updating it.
Account imported in 0:0:3
Account relationship added in 0:0:4
No purchasing phone number was found. Skipping this contact.
accounts payable contact for [account_name_2] exists. Updating it.
Contact imported in 0:0:3
Contact relationship saved in 0:0:0

User account for [username] already exists.
User import completed in 0:0:0
New account bean gotten in 0:0:0
Account search took 0:0:0
Found account for [account_name_3]. Updating it.
Account imported in 0:0:6
Account relationship added in 0:0:4
No purchasing phone number was found. Skipping this contact.
accounts payable contact for [account_name_3] exists. Updating it.
Contact imported in 0:0:4
Contact relationship saved in 0:0:1

I forgot to say a couple things in my last post, and I don’t see a way to edit it. Sorry for the double post.

First, I ran this a bunch of times. Each time, the numbers were a bit different, with eight seconds being my record high for any single reading. However, at no point did I see the search times go above zero. I also found no trend, such as times getting longer with each iteration of the for loop in the script.

Second, I enabled MySQL slow query logging, and set the threshold to five seconds. Since I was getting so many times over five seconds, I hoped to capture the exact queries taking up all that time, if indeed MySQL were the problem. So far, the log file has nothing in it. Oh, I also enabled MySQL caching, just to see if it would help. It has not, so far.

I feel like Sherlock Holmes whenever I come into this thread :slight_smile: I hope one day we can find out your mystery problem.

If the delays are when saving, you coudl try disabling AOD advanced search, or have a look at your Index to see if it became corrupted, or simply recreate it. Have a look here:

https://pgorod.github.io/Reindex-AOD/

You could also try to figure out if there is any logic_hook running when you save that record. Set your logs to debug level and search them logs for clues on either indexing or hooks.

Thanks for the ideas… But I have bad news. I followed the article’s instructions to reset my indexes, and I saw a small speed-up at first. Then I imported three users’ details instead of just one, and everything took as long as before.

I see nothing about indexing in the debug logs, but that may just mean I don’t know what I’m looking for. As to hooks, I haven’t made any. If a hook is in place, it came with SC and needs to be there, I assume.

Ultimately, I’m getting disconnect/reconnect calls constantly in the debug log, and I really feel like that’s the core of the problem. I just don’t have a clue why they happen, or where to start looking for answers. But the cause could be nothing to do with SQL directly, and the long pauses after disconnecting could be a symptom or result of something else. I don’t know the system well enough to know where to start looking, and the code chasing I’ve done thus far hasn’t gotten me very far. I’m open to any other ideas you or anyone else has. Is there anything else I can post that might reveal some detail that would be important?

Sorry to be such a pain. I just don’t know why this is happening, and only, it seems, to me. No one online that I’ve found has this problem, and I know it’s not my server or SQL instance. So far, the only slow query (query over five seconds, in my case) comes from Request Tracker, and there’s just the one. Despite all the times I’ve run this CRM import script, no queries log as being slow. The Request Tracker instance is stable, and my server looks okay overall. Nginx isn’t giving me problems, nor is php5-fpm. The CRM itself seems to run pretty well… Until I try to import. Then I get the problems I’ve been talking about. I’m so confused!

You know, sometimes things like this simply boil down to a failing hard drive or motherboard… something that hangs when it shouldn’t…

If it is a software problem, a bug, you might have a hard time finding it if nobody else seems to have it…

Why don’t you simply go for a more tested setup, Ubuntu + Apache + PHP 7.0 + MySQL?

I can set one up with SuiteCRM in around 10 minutes, using these instructions:

https://suitecrm.com/forum/installation-upgrade-help/11561-installing-on-ubuntu-16-04-1

My employer uses virtual servers for everything, so I can rule out hardware. :slight_smile: The benefits of living in the cloud!

As to a fresh setup, I can see if we have the resources to build another Linux server on our plan. I went with Debian + Nginx + MySQL because we already had a server with that setup running. It hosts our ticket system (Request Tracker) and an internal webpage or two. I’m more comfortable with Nginx config files than Apache, so I didn’t see a need to switch. But if SC runs best on Apache and Ubuntu, I can try that if I’m able to create another server. Failing that, I guess I could bring in a Raspberry Pi or see if we have an old computer lying around that no one needs anymore. Still, given how (comparatively) easy Request Tracker and OSTicket before it were to get working, I’m surprised that I’m having so much trouble with SC. I can also see about installing PHP7, but the SC installer said that my version (5.6, I believe) would work. I wonder if 7 has a new MySQL driver that may help, though? The problem here isn’t page load times or anything like that, but rather database write time, as far as I can tell.

The computers on the cloud also suffer from failing hardware :slight_smile: if it goes undetected, they might not change you to different hardware.

PHP 7 is highly recommend - much faster and definitely safer.

I’m sure Nginx is a very valid option, I’m just suggesting you try the other configuration to see if you get a better experience… I’m not promising you will, though. :slight_smile:

I have a Digital Ocean droplet I forgot about, so I’m going to try that. It has Debian, but I can at least try PHP7. Also, do you think updating to 7.9.7 instead of 7.9.6 would help? I noticed SC had been updated to 7.9.7 as I was finding the download link for my droplet. I’ll upgrade the main server either way, since there’s no user data to worry about yet even if something goes wrong, but I’m wondering if I can expect any improvement? Probably not, but you never know.