Hardware Recommendation for 30 - 40 users

ok, thank you, I’ll try that.
We also gonna setup a whole new vm and check if it’s maybe an configuration-problem in the vm.

Hi @danielduchon - two questions:

  • Are you on latest stable?
  • Are you using the CTI integration?

If your answer is no and yes it might be this issue: https://github.com/zammad/zammad/issues/2193

Other from that we made pretty good experience for these kind of issues with rbspy. I’ll document the process here in the hope that it will help someone some day (hopefully you @danielduchon :wink: ):

I’m curious what your recordings look like.

JFI: rbspy is production safe! It only reads information from the running ruby process. Feel free to dig deeper into the documentation of this wonderful tool and show some love to Julia.

Greetings from France :fr: :sunny: :baguette_bread:

as an aside, maybe someone who likes a bit of edutainment will want to check out the following.
rbspy rings a bell, there was an interesting podcast I listened to a few months ago with Julia, made me almost want to turn evil and learn Ruby. https://twit.tv/shows/floss-weekly/episodes/487

1 Like

Learning ruby was the best decision ever! Nothing bad or evil about it :wink: What a beautiful language :heart: Thanks for sharing. I’ll definitely check it out.

1 Like

We are on the latest version, available via apt. we enabled the cit-integration just for testing porposes, but deactivated it 2 days later. So at the moment, CTI is not enabled anymore.

Here are the formatted recordings:
Do you see anything?

<?xml version="1.0" standalone="no"?>
<!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd">
<svg version="1.1" width="1200" height="598" onload="init(evt)" viewBox="0 0 1200 598" xmlns="http://www.w3.org/2000/svg" xmlns:xlink="http://www.w3.org/1999/xlink">
<!-- Flame graph stack visualization. See https://github.com/brendangregg/FlameGraph for latest version, and http://www.brendangregg.com/flamegraphs.html for examples. -->
<!-- NOTES:  -->
<defs >
	<linearGradient id="background" y1="0" y2="1" x1="0" x2="0" >
		<stop stop-color="#eeeeee" offset="5%" />
		<stop stop-color="#eeeeb0" offset="95%" />
	</linearGradient>
</defs>
<style type="text/css">
	.func_g:hover { stroke:black; stroke-width:0.5; cursor:pointer; }
</style>
<script type="text/ecmascript">
<![CDATA[
	var details, searchbtn, matchedtxt, svg;
	function init(evt) {
		details = document.getElementById("details").firstChild;
		searchbtn = document.getElementById("search");
		matchedtxt = document.getElementById("matched");
		svg = document.getElementsByTagName("svg")[0];
		searching = 0;
	}

	// mouse-over for info
	function s(node) {		// show
		info = g_to_text(node);
		details.nodeValue = "Function: " + info;
	}
	function c() {			// clear
		details.nodeValue = ' ';
	}

	// ctrl-F for search
	window.addEventListener("keydown",function (e) {
		if (e.keyCode === 114 || (e.ctrlKey && e.keyCode === 70)) {
			e.preventDefault();
			search_prompt();
		}
	})

	// functions
	function find_child(parent, name, attr) {
		var children = parent.childNodes;
		for (var i=0; i<children.length;i++) {
			if (children[i].tagName == name)
				return (attr != undefined) ? children[i].attributes[attr].value : children[i];
		}
		return;
	}
	function orig_save(e, attr, val) {
		if (e.attributes["_orig_"+attr] != undefined) return;
		if (e.attributes[attr] == undefined) return;
		if (val == undefined) val = e.attributes[attr].value;
		e.setAttribute("_orig_"+attr, val);
	}
	function orig_load(e, attr) {
		if (e.attributes["_orig_"+attr] == undefined) return;
		e.attributes[attr].value = e.attributes["_orig_"+attr].value;
		e.removeAttribute("_orig_"+attr);
	}
	function g_to_text(e) {
		var text = find_child(e, "title").firstChild.nodeValue;
		return (text)
	}
	function g_to_func(e) {
		var func = g_to_text(e);
		// if there's any manipulation we want to do to the function
		// name before it's searched, do it here before returning.
		return (func);
	}
	function update_text(e) {
		var r = find_child(e, "rect");
		var t = find_child(e, "text");
		var w = parseFloat(r.attributes["width"].value) -3;
		var txt = find_child(e, "title").textContent.replace(/\([^(]*\)$/,"");
		t.attributes["x"].value = parseFloat(r.attributes["x"].value) +3;

		// Smaller than this size won't fit anything
		if (w < 2*12*0.59) {
			t.textContent = "";
			return;
		}

		t.textContent = txt;
		// Fit in full text width
		if (/^ *$/.test(txt) || t.getSubStringLength(0, txt.length) < w)
			return;

		for (var x=txt.length-2; x>0; x--) {
			if (t.getSubStringLength(0, x+2) <= w) {
				t.textContent = txt.substring(0,x) + "..";
				return;
			}
		}
		t.textContent = "";
	}

	// zoom
	function zoom_reset(e) {
		if (e.attributes != undefined) {
			orig_load(e, "x");
			orig_load(e, "width");
		}
		if (e.childNodes == undefined) return;
		for(var i=0, c=e.childNodes; i<c.length; i++) {
			zoom_reset(c[i]);
		}
	}
	function zoom_child(e, x, ratio) {
		if (e.attributes != undefined) {
			if (e.attributes["x"] != undefined) {
				orig_save(e, "x");
				e.attributes["x"].value = (parseFloat(e.attributes["x"].value) - x - 10) * ratio + 10;
				if(e.tagName == "text") e.attributes["x"].value = find_child(e.parentNode, "rect", "x") + 3;
			}
			if (e.attributes["width"] != undefined) {
				orig_save(e, "width");
				e.attributes["width"].value = parseFloat(e.attributes["width"].value) * ratio;
			}
		}

		if (e.childNodes == undefined) return;
		for(var i=0, c=e.childNodes; i<c.length; i++) {
			zoom_child(c[i], x-10, ratio);
		}
	}
	function zoom_parent(e) {
		if (e.attributes) {
			if (e.attributes["x"] != undefined) {
				orig_save(e, "x");
				e.attributes["x"].value = 10;
			}
			if (e.attributes["width"] != undefined) {
				orig_save(e, "width");
				e.attributes["width"].value = parseInt(svg.width.baseVal.value) - (10*2);
			}
		}
		if (e.childNodes == undefined) return;
		for(var i=0, c=e.childNodes; i<c.length; i++) {
			zoom_parent(c[i]);
		}
	}
	function zoom(node) {
		var attr = find_child(node, "rect").attributes;
		var width = parseFloat(attr["width"].value);
		var xmin = parseFloat(attr["x"].value);
		var xmax = parseFloat(xmin + width);
		var ymin = parseFloat(attr["y"].value);
		var ratio = (svg.width.baseVal.value - 2*10) / width;

		// XXX: Workaround for JavaScript float issues (fix me)
		var fudge = 0.0001;

		var unzoombtn = document.getElementById("unzoom");
		unzoombtn.style["opacity"] = "1.0";

		var el = document.getElementsByTagName("g");
		for(var i=0;i<el.length;i++){
			var e = el[i];
			var a = find_child(e, "rect").attributes;
			var ex = parseFloat(a["x"].value);
			var ew = parseFloat(a["width"].value);
			// Is it an ancestor
			if (1 == 0) {
				var upstack = parseFloat(a["y"].value) > ymin;
			} else {
				var upstack = parseFloat(a["y"].value) < ymin;
			}
			if (upstack) {
				// Direct ancestor
				if (ex <= xmin && (ex+ew+fudge) >= xmax) {
					e.style["opacity"] = "0.5";
					zoom_parent(e);
					e.onclick = function(e){unzoom(); zoom(this);};
					update_text(e);
				}
				// not in current path
				else
					e.style["display"] = "none";
			}
			// Children maybe
			else {
				// no common path
				if (ex < xmin || ex + fudge >= xmax) {
					e.style["display"] = "none";
				}
				else {
					zoom_child(e, xmin, ratio);
					e.onclick = function(e){zoom(this);};
					update_text(e);
				}
			}
		}
	}
	function unzoom() {
		var unzoombtn = document.getElementById("unzoom");
		unzoombtn.style["opacity"] = "0.0";

		var el = document.getElementsByTagName("g");
		for(i=0;i<el.length;i++) {
			el[i].style["display"] = "block";
			el[i].style["opacity"] = "1";
			zoom_reset(el[i]);
			update_text(el[i]);
		}
	}

	// search
	function reset_search() {
		var el = document.getElementsByTagName("rect");
		for (var i=0; i < el.length; i++) {
			orig_load(el[i], "fill")
		}
	}
	function search_prompt() {
		if (!searching) {
			var term = prompt("Enter a search term (regexp " +
			    "allowed, eg: ^ext4_)", "");
			if (term != null) {
				search(term)
			}
		} else {
			reset_search();
			searching = 0;
			searchbtn.style["opacity"] = "0.1";
			searchbtn.firstChild.nodeValue = "Search"
			matchedtxt.style["opacity"] = "0.0";
			matchedtxt.firstChild.nodeValue = ""
		}
	}
	function search(term) {
		var re = new RegExp(term);
		var el = document.getElementsByTagName("g");
		var matches = new Object();
		var maxwidth = 0;
		for (var i = 0; i < el.length; i++) {
			var e = el[i];
			if (e.attributes["class"].value != "func_g")
				continue;
			var func = g_to_func(e);
			var rect = find_child(e, "rect");
			if (rect == null) {
				// the rect might be wrapped in an anchor
				// if nameattr href is being used
				if (rect = find_child(e, "a")) {
				    rect = find_child(r, "rect");
				}
			}
			if (func == null || rect == null)
				continue;

			// Save max width. Only works as we have a root frame
			var w = parseFloat(rect.attributes["width"].value);
			if (w > maxwidth)
				maxwidth = w;

			if (func.match(re)) {
				// highlight
				var x = parseFloat(rect.attributes["x"].value);
				orig_save(rect, "fill");
				rect.attributes["fill"].value =
				    "rgb(230,0,230)";

				// remember matches
				if (matches[x] == undefined) {
					matches[x] = w;
				} else {
					if (w > matches[x]) {
						// overwrite with parent
						matches[x] = w;
					}
				}
				searching = 1;
			}
		}
		if (!searching)
			return;

		searchbtn.style["opacity"] = "1.0";
		searchbtn.firstChild.nodeValue = "Reset Search"

		// calculate percent matched, excluding vertical overlap
		var count = 0;
		var lastx = -1;
		var lastw = 0;
		var keys = Array();
		for (k in matches) {
			if (matches.hasOwnProperty(k))
				keys.push(k);
		}
		// sort the matched frames by their x location
		// ascending, then width descending
		keys.sort(function(a, b){
			return a - b;
		});
		// Step through frames saving only the biggest bottom-up frames
		// thanks to the sort order. This relies on the tree property
		// where children are always smaller than their parents.
		var fudge = 0.0001;	// JavaScript floating point
		for (var k in keys) {
			var x = parseFloat(keys[k]);
			var w = matches[keys[k]];
			if (x >= lastx + lastw - fudge) {
				count += w;
				lastx = x;
				lastw = w;
			}
		}
		// display matched percent
		matchedtxt.style["opacity"] = "1.0";
		pct = 100 * count / maxwidth;
		if (pct == 100)
			pct = "100"
		else
			pct = pct.toFixed(1)
		matchedtxt.firstChild.nodeValue = "Matched: " + pct + "%";
	}
	function searchover(e) {
		searchbtn.style["opacity"] = "1.0";
	}
	function searchout(e) {
		if (searching) {
			searchbtn.style["opacity"] = "1.0";
		} else {
			searchbtn.style["opacity"] = "0.1";
		}
	}
]]>
</script>
<rect x="0.0" y="0" width="1200.0" height="598.0" fill="url(#background)"  />
<text text-anchor="middle" x="600.00" y="24" font-size="17" font-family="Verdana" fill="rgb(0,0,0)"  >Icicle Graph</text>
<text text-anchor="" x="10.00" y="581" font-size="12" font-family="Verdana" fill="rgb(0,0,0)" id="details" > </text>
<text text-anchor="" x="10.00" y="24" font-size="12" font-family="Verdana" fill="rgb(0,0,0)" id="unzoom" onclick="unzoom()" style="opacity:0.0;cursor:pointer" >Reset Zoom</text>
<text text-anchor="" x="1090.00" y="24" font-size="12" font-family="Verdana" fill="rgb(0,0,0)" id="search" onmouseover="searchover()" onmouseout="searchout()" onclick="search_prompt()" style="opacity:0.1;cursor:pointer" >Search</text>
<text text-anchor="" x="1090.00" y="581" font-size="12" font-family="Verdana" fill="rgb(0,0,0)" id="matched" > </text>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>block in &lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/exe/bundle line 30 (169 samples, 100.00%)</title><rect x="10.0" y="116" width="1180.0" height="15.0" fill="rgb(224,60,24)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="126.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >block in &lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/exe/bundle line 30</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor.rb line 387 (169 samples, 100.00%)</title><rect x="10.0" y="372" width="1180.0" height="15.0" fill="rgb(245,207,45)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="382.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor.rb line 387</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 44 (169 samples, 100.00%)</title><rect x="10.0" y="468" width="1180.0" height="15.0" fill="rgb(213,16,4)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="478.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 44</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;c function&gt; - unknown line 0 (169 samples, 100.00%)</title><rect x="10.0" y="276" width="1180.0" height="15.0" fill="rgb(225,66,44)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="286.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;c function&gt; - unknown line 0</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands.rb line 16 (169 samples, 100.00%)</title><rect x="10.0" y="324" width="1180.0" height="15.0" fill="rgb(223,218,8)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="334.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands.rb line 16</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/server.rb line 297 (169 samples, 100.00%)</title><rect x="10.0" y="484" width="1180.0" height="15.0" fill="rgb(209,142,10)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="494.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/rack-2.0.5/lib/rack/server.rb line 297</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;main&gt; - /opt/zammad/bin/bundle line 3 (169 samples, 100.00%)</title><rect x="10.0" y="52" width="1180.0" height="15.0" fill="rgb(249,63,23)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="62.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;main&gt; - /opt/zammad/bin/bundle line 3</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>kernel_load - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli/exec.rb line 74 (169 samples, 100.00%)</title><rect x="10.0" y="260" width="1180.0" height="15.0" fill="rgb(219,4,44)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="270.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >kernel_load - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli/exec.rb line 74</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/exe/bundle line 22 (169 samples, 100.00%)</title><rect x="10.0" y="84" width="1180.0" height="15.0" fill="rgb(205,15,38)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="94.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;top (required)&gt; - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/exe/bundle line 22</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/command/base.rb line 63 (169 samples, 100.00%)</title><rect x="10.0" y="356" width="1180.0" height="15.0" fill="rgb(214,171,53)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="366.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/command/base.rb line 63</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;c function&gt; - unknown line 0 (169 samples, 100.00%)</title><rect x="10.0" y="436" width="1180.0" height="15.0" fill="rgb(230,145,20)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="446.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;c function&gt; - unknown line 0</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/puma/cluster.rb line 507 (169 samples, 100.00%)</title><rect x="10.0" y="532" width="1180.0" height="15.0" fill="rgb(250,189,9)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="542.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/puma/cluster.rb line 507</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>block in perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 135 (169 samples, 100.00%)</title><rect x="10.0" y="452" width="1180.0" height="15.0" fill="rgb(237,174,48)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="462.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >block in perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 135</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>invoke - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/command.rb line 46 (169 samples, 100.00%)</title><rect x="10.0" y="340" width="1180.0" height="15.0" fill="rgb(218,59,53)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="350.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >invoke - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/command.rb line 46</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor.rb line 369 (169 samples, 100.00%)</title><rect x="10.0" y="180" width="1180.0" height="15.0" fill="rgb(246,198,3)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="190.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor.rb line 369</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;c function&gt; - unknown line 0 (169 samples, 100.00%)</title><rect x="10.0" y="548" width="1180.0" height="15.0" fill="rgb(251,16,19)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="558.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;c function&gt; - unknown line 0</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/base.rb line 444 (169 samples, 100.00%)</title><rect x="10.0" y="148" width="1180.0" height="15.0" fill="rgb(229,49,5)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="158.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/base.rb line 444</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>with_friendly_errors - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/friendly_errors.rb line 121 (169 samples, 100.00%)</title><rect x="10.0" y="100" width="1180.0" height="15.0" fill="rgb(225,142,31)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="110.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >with_friendly_errors - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/friendly_errors.rb line 121</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor/command.rb line 31 (169 samples, 100.00%)</title><rect x="10.0" y="404" width="1180.0" height="15.0" fill="rgb(246,10,7)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="414.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor/command.rb line 31</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>invoke_command - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor/invocation.rb line 126 (169 samples, 100.00%)</title><rect x="10.0" y="388" width="1180.0" height="15.0" fill="rgb(244,98,23)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="398.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >invoke_command - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/thor-0.20.0/lib/thor/invocation.rb line 126</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 10 (169 samples, 100.00%)</title><rect x="10.0" y="132" width="1180.0" height="15.0" fill="rgb(209,6,19)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="142.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >start - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 10</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;c function&gt; - unknown line 0 (169 samples, 100.00%)</title><rect x="10.0" y="68" width="1180.0" height="15.0" fill="rgb(206,223,48)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="78.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;c function&gt; - unknown line 0</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>invoke_command - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/invocation.rb line 126 (169 samples, 100.00%)</title><rect x="10.0" y="196" width="1180.0" height="15.0" fill="rgb(217,93,35)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="206.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >invoke_command - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/invocation.rb line 126</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 130 (169 samples, 100.00%)</title><rect x="10.0" y="420" width="1180.0" height="15.0" fill="rgb(248,130,54)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="430.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >perform - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/railties-5.1.5/lib/rails/commands/server/server_command.rb line 130</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;c function&gt; - unknown line 0 (169 samples, 100.00%)</title><rect x="10.0" y="308" width="1180.0" height="15.0" fill="rgb(217,228,48)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="318.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;c function&gt; - unknown line 0</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/command.rb line 31 (169 samples, 100.00%)</title><rect x="10.0" y="212" width="1180.0" height="15.0" fill="rgb(236,148,22)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="222.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/vendor/thor/lib/thor/command.rb line 31</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 20 (169 samples, 100.00%)</title><rect x="10.0" y="164" width="1180.0" height="15.0" fill="rgb(228,92,52)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="174.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >dispatch - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 20</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>&lt;top (required)&gt; - /opt/zammad/script/rails line 6 (169 samples, 100.00%)</title><rect x="10.0" y="292" width="1180.0" height="15.0" fill="rgb(212,52,37)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="302.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >&lt;top (required)&gt; - /opt/zammad/script/rails line 6</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli/exec.rb line 37 (169 samples, 100.00%)</title><rect x="10.0" y="244" width="1180.0" height="15.0" fill="rgb(231,23,48)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="254.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli/exec.rb line 37</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>exec - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 360 (169 samples, 100.00%)</title><rect x="10.0" y="228" width="1180.0" height="15.0" fill="rgb(221,6,52)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="238.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >exec - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/bundler-1.15.2/lib/bundler/cli.rb line 360</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/puma/launcher.rb line 194 (169 samples, 100.00%)</title><rect x="10.0" y="516" width="1180.0" height="15.0" fill="rgb(236,171,6)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="526.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/puma/launcher.rb line 194</text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>all (169 samples, 100%)</title><rect x="10.0" y="36" width="1180.0" height="15.0" fill="rgb(228,175,50)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="46.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  ></text>
</g>
<g class="func_g" onmouseover="s(this)" onmouseout="c()" onclick="zoom(this)">
<title>run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/rack/handler/puma.rb line 69 (169 samples, 100.00%)</title><rect x="10.0" y="500" width="1180.0" height="15.0" fill="rgb(211,198,31)" rx="2" ry="2" />
<text text-anchor="" x="13.00" y="510.5" font-size="12" font-family="Verdana" fill="rgb(0,0,0)"  >run - /opt/zammad/vendor/bundle/ruby/2.4.0/gems/puma-3.11.0/lib/rack/handler/puma.rb line 69</text>
</g>
</svg>

OK, we’ve narrowed it down. It always occurs when a new session is created (e.g. when someone logs on.). Then puma consumes about 50 - 70% of the CPU power of all cores for about 5 minutes and blocks zammad completely. During this time, no new actions are possible in the UI and the users sometimes get an Error 500.

Hi @danielduchon - thanks for the heads up. The file you send me is an SVG file which can be opened via e.g. a browser and looks like this:

This may look rather cryptical. It reads like a timeline where the left side is the start and the right side is the end. The most top line is the whole process and every line below is a sub method call, sub-sub method call and so on. Usually this looks more clustered. In your case you can see that the whole time is spend in <c function> - unknown line 0. Therefore the line above is interesting: It’s in the cluster.rb file of puma (the Ruby web-/application server). Looking at the source code revealed that this line starts/executes sub processes.

TL;DR: It looks like you got the wrong process :thinking:

ok, I must have done the trace with the cluster PID.
Since I can’t upload SVG files here, I uploaded the files of the 8 puma processes in our Google Drive. I hope that’s okay: https://drive.google.com/drive/folders/1OLdKXG9_fV5XtFm91nxJa3ozh_RjB2iT?usp=sharing

These files are perfect. Here is a screenshot of the relevant part of one of those files which makes the situation clear:

So we read it from top down: The request starts at the show method of the file app/controllers/users_controller.rb. Which is a request to fetch all data for one certain user. Log entries for these requests usually look something like this:

I, [2018-08-31T18:39:10.505544 #95878]  INFO -- : Processing by UsersController#show as JSON
I, [2018-08-31T18:39:10.508053 #95878]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1535730254901", "id"=>"2"}

The id parameter indicates for which user the information gets fetched. In this example it’s the user with the ID 2.

For your situation it would be interesting which User ID(s) cause(s) the CPU load. Please have a look at in your production.log file and check the most recent UsersController#show entries with their User ID parameters. You can manually execute such a request by opening a browser window with the URL https://your.zammad.tld/api/v1/users/*user_id* (e.g. https://your.zammad.tld/api/v1/users/2). It would be good to know how long such a call takes and if you can see a CPU load peak for a new process.

After that I’ll be able pro provide a debugging script and see where the time is spend and what the expensive operations are.

I assume that there is a Organization with a lot of users assigned. To verify this please run the following code in your Zammad Rails console and post the anonymized output here:

User.where.not(organization_id: nil).group(:organization_id).count.each_with_object({}) { |(o_id, count), result| result[ "#{Organization.find(o_id).name} ID: #{o_id}" ] =  count }

The output should look like this:

{"Zammad Foundation ID: 1"=>1,
 "Name der Firma1 ID: 2"=>10,
 "Name der Firma2 ID: 3"=>27,
 "Name der Firma4 ID: 4"=>6,
 "Name der Firma5 ID: 5"=>14,
 "Name der Firma6 ID: 6"=>11,
 "Name der Firma9 ID: 7"=>8,
 "Name der Firma14 ID: 8"=>16,
 "Name der Firma16 ID: 9"=>23,
 "Name der Firma17 ID: 10"=>5,
 "Name der Firma18 ID: 11"=>3}

thank you for your help.

the only users who log on to our system are our users. As already suspected, they are all bundled in one organization:

{
"Zammad Foundation ID: 1"=>1,
"Name der Firma1 ID: 2"=>95,
"Name der Firma2 ID: 4"=>1,
"Name der Firma3 ID: 5"=>1,
"Name der Firma4 ID: 6"=>2,
"Name der Firma5 ID: 7"=>1
}

The API call takes 33 seconds the first time I log in and 1.5 seconds the second time. In both cases, however, a new process is triggered which raises the peak.

It was definitely the organization that triggered the problem. After removing all users from all organizations, the CPU usage of all cores is about 0.5%. But this can be a dirty workaround at most because we need the organizations and it is predictable that we will have customers with 30 and more users.

I can’t help with the bug, but maybe try updating to the latest release, create a new organisation and user and see if that user triggers the issue?

Hi guys. I still don’t get how the notification system works :thinking: I haven’t received any email notification for your replies. Anyhow, thanks @danielduchon for the deeper investigation. Fetching (uncached) assets of a big Organization may take some time. However, on my local machine it takes only 2 seconds to fetch an Organization with 100 Users with a totally blank cache. With a pre-heated cache it only takes 0.02 seconds.
You’re saying that the second time you perform the login it’s done much faster. Does this mean that the CPU peak for this process is that short as well?

I’ve build a little debugging script that should give more insights on where the time is spend and if it’s only a certain User that makes this request so slow.

To use this script please do the following:

  1. Add the following line to your Gemfile file in your Zammad directory:
    gem 'ruby-prof'
  2. Run bundle install (or zammad run bundle install - depending on your setup)
  3. Create a file called profiling-issue.rb in your Zammad directory.
  4. Place the code from below in the file.
  5. Run the file with your Organization as a parameter via rails r profiling-issue.rb *ORGANIZATION_ID* (or zammad run rails r profiling-issue.rb *ORGANIZATION_ID* - depending on your setup)
  6. Provide the following files here that were created in your Zammad directory (please note that instead of the * there will be a number):
  • profiling.empty-cache.*.html
  • profiling.pre-heated-cache.*.html
  • profiling.no-asset-reusage.*.html
  • no-asset-reusage.txt

There is no confidential data logged/included in these files.

  1. Remove the added line from your Gemfile
  2. Run bundle install (or zammad run bundle install - depending on your setup)

The script:

organization_id = ARGV[0]
abort "Missing Organization ID parameter." if organization_id.blank?

puts "Define helper method that profiles the given block..."
def profile_as(profile)
  RubyProf.measure_mode = RubyProf::WALL_TIME

  RubyProf.start

  profle_time_start = Time.now.to_f
  yield
  profle_time_total = Time.now.to_f - profle_time_start

  results = RubyProf.stop

  File.open("profiling.#{profile}.#{profle_time_total}.html", 'w') do |out|
    # RubyProf::FlameGraphPrinter.new(results).print(out)
    RubyProf::CallStackPrinter.new(results).print(out)
  end
end

puts "Finding Organization with ID #{organization_id} ..."
organization = Organization.find(organization_id)

puts "Switch over to (clean) in-memory cache..."
Rails.cache = ActiveSupport::Cache.lookup_store(:memory_store, { size: 200.megabytes })

puts "Start actual profiling for 'empty-cache'..."
profile_as('empty-cache') do
  organization.assets({})
end

puts "Start actual profiling for 'pre-heated-cache'..."
profile_as('pre-heated-cache') do
  organization.assets({})
end

puts "Start actual profiling for 'no-asset-reusage'..."
run_time_start = Time.now.to_f
time_map       = {}
profile_as('no-asset-reusage') do

  time_map = organization.member_ids.each_with_object({}) do |user_id, result|

    user = User.lookup(id: user_id)
    next if !user

    asset_time_start = Time.now.to_f
    user.assets({})
    result[user_id] = Time.now.to_f - asset_time_start
  end
end

File.open('no-asset-reusage.txt', 'w') do |file|
  time_map.sort_by(&:last).reverse.each do |user_id, seconds|
    file.puts "It took #{seconds} seconds to fetch assets for User with ID #{user_id}."
  end
  file.puts "It took #{Time.now.to_f - run_time_start} seconds for fetching all assets (without reusage)."
end

puts "DONE!"

I’m curious on what the output will look like :nerd_face:

EDIT:
Please make sure to get your system back in the state where we can reproduce the issue (Users assigned to Organization)

Okay, but I have to do that at the weekend. Otherwise my users will knock my head off me…

ok, i made the changes and executed the command. I loaded the files back into my GoogleDrive because they are very large.
Here again the link https://drive.google.com/drive/folders/1OLdKXG9_fV5XtFm91nxJa3ozh_RjB2iT?usp=sharing

Since there are no users logged in at the weekend, I logged in ten times for testing purposes and put 300 users into the organization to create some load.

You might have to mention @thorsteneckel because he doesn’t seem to be getting email notifications for replies, not sure if he gets them for mentions either but won’t hurt.

Thanks @chesty and @danielduchon. I reviewed the provided files and they look good to me. The asset gathering takes 4.7 seconds after there is no cache at all. After the cacheable data was cached it took only 0.06 seconds! This is both far away from the 30 seconds we were talking about earlier. I think the system isn’t in the state where the error occurs anymore OR if it’s that fast on the weekend the system doesn’t scale when actively used. Maybe you should add some more CPU power to the machine?

hi @thorsteneckel . please excuse the late reaction but due to some work I couldn’t answer earlier. I’ m going to monitor this for now. If the behavior occurs again, I immediately start the recording and post the data here. More CPU is an option I keep in mind. Thanks for the tip.

2 Likes

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.