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!
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:
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:
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?
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?
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.
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 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:
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!
My employer uses virtual servers for everything, so I can rule out hardware. 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 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.
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.