Golang: Is The Mutex Is Locked, And Finding The Line Number That Did It

Quick summary of the situation, giving enough details to highlight the problem but not giving proprietary information away...

I have a program that queries a service which in turn talks to a database. The database holds records identified by unique rowkeys. I want to read all of the records, as far as the database knows of their existence, which I can get through an API call, iterating in discrete steps.

The utility I created pulls a batch of these keys, then iterates over them one by one to determine if I want to make a call to the service to pull the whole record (I don't need to if the key was already called before or previously analyzed on a previous run of the program.)

Seems relatively simple, but this is a big database and I'm going to be running this for a long time. Also, these servers are in the same network, so the connections are pretty fast and furious...if I overestimate some capacity, I'm going to really hammer the servers and the last thing I want to do is create an internal DDoS.

To that end, this utility keeps a number of running stats using structs that are updated by the various goroutines. To keep things synced up, I use an embedded lock on the structs.

(Yeah, that's a neat feature...works like this:)

type stctMyStruct struct {
sync.Mutex
intCounter int
}

After that, it's a simple matter of instantiating a struct and using it.

var strctMyStruct stctMyStruct

strctMyStruct.Lock()
strctMyStruct.intCounter = strctMyCounter.intCounter + 1
strctMyStruct.Unlock()

Because the utility is long-running and I wanted to keep tabs on different aspects of performance, I had several structs with embedded mutexes being updated by various goroutines. Using timers in separate routines, the stats were aggregated and turned into a string of text that could be printed to the console, redirected to a file or sent to a web page (I wanted a lot of options for monitoring, obviously.)

At some point I introduced a new bug in the program. My local system was relatively slow when it came to processing the keys (it's not just iterating over them...it evaluates them, sorts some things, picks through information in the full record...) and when I transferred it to the internal network, the jump in speed accelerated exposure of a timing issue. The program output...and processing...and web page displaying the status of the utility...all froze. But the program was still running, according to process monitoring.

I first thought it was a race condition...something is getting locked and not releasing it. But how can I tell if a routine is blocked by a locked struct? Golang does not have a call that will tell you if a mutex is locked, because that would lead to a race condition. In the time it takes to make the call and get the reply, that lock could have changed status.

Okay...polling the state of mutexes is out of the question. But what isn't out of the question is tracking when a request for a lock is granted.

First I changed the struct to have an addressable member for setting the state of the lock.

type stctMyStruct struct {
lock sync.Mutex
intCounter int
}

Next I created some methods for the struct to handle the locking and unlocking.

func (strctMyStruct *stctMyStruct) LockIt(intLine int) {

chnLocksTracking <- "Requesting lock to strctMyStruct by line " +strconv.Itoa(intLine)

tmElapsed := time.Now()
strctMyStruct.lock.Lock()

defer func() {

chnLocksTracking <- "Lock granted to strctMyStruct by line " + strconv.Itoa(intLine) + " in " + time.Since(tmElapsed).String()
}()

return
}

func (strctMyStruct *stctMyStruct) UnlockIt(intLine int) {

chnLocksTracking <- "Requesting unlock to strctMyStruct by line " +strconv.Itoa(intLine)

tmElapsed := time.Now()
strctMyStruct.lock.Unlock()

defer func() {

chnLocksTracking <- "Unlock granted to strctMyStruct by line " + strconv.Itoa(intLine) + " in " + time.Since(tmElapsed).String()
}()

return
}

LockIt() and UnlockIt() methods are now added to instances of stctMyStruct. When called, the function first sends a string into a channel with a dedicated goroutine on the other end digesting and logging messages; the first acts as a notification that the caller is "going to ask for a change in the mutex."

If the struct is locked, the operation will block. Once it is available, the function returns, and in the process runs the defer function which sends the granted message down the channel along with the elapsed time to get the request granted.

How does it know about the line number?

There's actually a library function that can help with that; my problem is that it returns too much information to not be a little unwieldy. To get around that, I created a small wrapper function.

func GetLine() int {
_,_,intLine, _ := runtime.Caller(1)
return intLine
}

If you look at the documentation you can get the specifics of what is returned, but Caller() can unwind the stack a from a call by the number of steps you use as an argument and return the line number, package/module, etc...in my particular case I'm using one source file so I only needed the line number.

Using this, you can insert function calls to lock and unlock the structs as needed. I added the methods to each struct that had a mutex or rwmutex. Using them is as simple as:

strctMyStruct.LockIt(GetLine())

This solution provided a way to trace what was happening, but there is a performance cost. Defer() adds a few fractions of a second each time it's called and I used a lot of locks throughout the program which added up to a significant performance hit. Using this technique is good for debugging, but you have to decide if you want to incur the overhead or find a way to compensate for it.

So what was my lock issue?

I set the goroutine monitoring the locks to dump information to a file and traced the requests vs. granted mutex changes. There was a race condition in a function I used that summarized aggregated information; A lock near the beginning of the summary was granted, and while pulling other information, it requested another lock. The second one was an operation on a struct that was held by a process waiting to get a lock on what was being held by the beginning of the summarize function.

It was a circular resource contention. Function A held a resource that Function B wanted, and Function B had a resource function A wanted. The solution was to add more granular locking, which added more calls but in the end meant (hopefully) there would be only one struct locked at a time within a given function.

Lesson learned: when using locks, keep the calls as tight and granular as possible, and avoid overlapping locks as much as possible or you may end up with a deadlock that Go's runtime wouldn't detect!

Golang Web Server: Don't Do This

I still consider myself new to programming. The new job allows me to create a lot of small system tools using Go mostly for augmenting monitoring and create utilities to replace manual API calls using JQ and CURL with single executables created in Go. It's been a wonderful learning experience.

Sometimes I try to add some new features to utilities that are snazzy but also a bit of an experiment.

This is a bit of reflection on the design I originally used and I am not in a mood to pull out layers of source code to show what I had done, especially if no one is asking for it. But I will describe the basic design in an effort to not only avoid implementing it that way again but to warn others not to make the same design pattern mistake.

The utility is mainly a long-running process that is interrogating one of our services for database information. It gets raw data from the database, pulls some stats like record size and type, and tallies the information. Millions and millions of records.

What if, I thought, I provided a peek into what the state of the tallying is beyond what I already had showing? It would output a count of some basic information as a one-liner every thirty seconds to the console, but that wasn't good enough. I thought, why not create a web interface that would output a simple text page of information?

Go loves channels. And I had several "worker goroutines" that handled specific tasks in the tally program, passing messages to a coordination process that serialized scheduling record analysis, directing results, and monitoring the state of various workers. Breaking them up made things pretty fast once I stuck in a few tweaks here and there.

Adding a web server routine wasn't hard. Then I thought, I could just add a couple of channels to plug them into routines that held statistics.

Here's where I made what later turned into a mistake.

Instead of individual handlers, I created a single handler that took message strings via channels. The messages consisted of a random ID and a type, where the type was the page request.

The reader on the other side of the channel split the message, used a select{} to determine which page it should construct, and returned through another channel the page with that ID string prepended. The receiver on the other side would look for the message and see if the ID belonged to its request. If it wasn't the proper ID, it just re-fed it to the channel, hoping that the right recipient would pick it up later, and the next message in the channel was intended for that particular reader. Line by line the page was fed back down the channel, with the ID attached to each message, until the ID was attached to a message: "END OF PAGE", at which point the page was done and connection closed.

Don't do that.

The thing is, this seemed to work. I opened a web browser, opened the page, and it worked. I could request the different pages and it worked just fine.

It worked until one page got kind of big and I opened two web pages to the server. Something seemed to get "stuck." One of my statuses gave a snapshot of the fill state of some channels and I noticed some of the web-related channels were...throbbing? Growing huge and slipping down, as if revving up with more lines of messages than should possibly be needed. Something was getting misdirected and the lightweight speed of goroutines meant it was flooding channels with useless information.

No problem, I thought. I'll add a third field, a counter, which once it reached a certain level would simply discard the message. The web page was meant to be read by a person who was trying to get some stats on the status of this utility while it was running, not the general public...refresh the page, hopefully you'll get a working reply that time. Sloppy, but might work.

Tested again. It seemed to keep the channels from getting as clogged up, but I still had some kind of crosstalk that when pages grew larger, and it wasn't hard to create some kind of denial of service from the web server when two different pages were opened. It almost seemed as if sometimes the two pages got completely confused which tab was supposed to get what page.

Maybe it was too easy to get messages mixed up because pages were feeding line by line. I went through the page composition and instead of feeding each line through, I had the process create one big string and feed the result.

This cut down on responsiveness but increased reliability. Kind of. It was significant, but not enough to be proud of. If anyone tried pulling a web page from the utility while someone else used it there was a non-zero chance it would get a weirdly formatted page, if not a timeout.

After finishing some work on other utilities, I decided to refactor the 4 web pages into their own handlers with separate functions and move some of the information being read into global structs with mutex's for protection. Before making the change I ran a test with Bombardier, a handing web server throughput tester. The test totally choked on the channel handler architecture.

I refactored, separated out the page composition into individual handlers, and eliminated channels for web page feeding. No more IDs. No more parsing out replies. No more tracking how many times this particular message is making rounds before "expiring" it.

Bombardier hammered away on the server with no issues. Multiple tabs reading different web pages? No problem. The biggest trigger for problems, clicking back or a link to one of the other pages while a large page hadn't finished rendering, was no longer a problem.

What I wanted to do was find a way to read a URL request and use one handler to interpret what the client wanted, so I didn't need a number of individual handlers defined. I'm pretty sure I still could do that, but I think the weakness was in using channels with an associated ID to parse replies back to the client from a dedicated goroutine holding stats.

The solution I ended up using was individual functions that read from a global struct holding the current state of statistics, and this was protected with a lot of locking.

I suppose another way to do it, with channels, would be finding a way to spawn dedicated channels with each request so the replies didn't need parsing or redirecting; a channel with multiple readers has no guarantee of who is going to get the message at what point. This kind of fix seemed needlessly complicated, though.

I suppose I could also have enhanced the global statistics struct to have functions associated with it, so calls could be made that would automatically lock and reply with information requested by callers. The utility is relatively small, though, and I thought that implementing that would have been more complicated than necessary. I'm not sure if this would enhance the speed of the program, though, and may be worth trying for the learning benefit.

But what I definitely now know is not to pass web pages as composed lines with an ID tagged down a shared channel for a reader to parse and decided, "Is this line meant for me? No? Here, back into the channel you go, floating rubber ducky of information, while I read the next ducky...float away!"

Don't do that.

Reflection on Coding

There's a subject I've been thinking about lately. I suppose it's more of a feeling than a topic; I'm not even sure how to put it into words.

I have a vague feeling that I've discussed it before, too. In some form. On the other hand, maybe writing about it will help get it out of my head.

The best I've managed to do to express this feeling is to frame it as "elegant beauty," or a kind of beauty that comes from expression through the logic of programming.

It's not that this is an entirely new concept. I've often read descriptions of Ruby as poetic, and there are other works that try examining questions like whether programming is more art than science, or whether programming is poetry.

Perhaps part of this is my own brains weird wiring. I sometimes have trouble understanding poetry; good poetry can "work" on so many levels. Clever word use, double entendre, use of linguistic beats to emphasize points, references to other events and works, parallels to other art forms...I'm sure my wife, an English major, is able to expound on (and expand) the topic far more than I.

Programming adds yet another dimension: it is functional. It takes a language, with its own unique grammar and syntax, and processes input into something else. It's an expression of formulas through rules. If you get the syntax wrong, your work won't compile into a finished product. Programming is notoriously unforgiving when straying from the language rules.

And yet programs that take a set of input and produce the same output can still have so much variety!

I suppose a simple example can use the infamous FizzBuzz program. It's a staple of many a coding interview; relatively simple, it has, over time, become almost cliche (and in some circles, despised, depending on the blogs you read and the type of programmer bemoaning how demeaning it is to be asked to demonstrate it...)

The rules are simple; usually some variant of, "Count from 1 to 100, and if a number is divisible by 3, print "Fizz." If it is divisible by 5, print "Buzz". If it is divisible by 3 and 5, print "FizzBuzz." Otherwise, print the number.

The simplest and most crude way to program this is to literally lay out a program that counts from 0 to 100 and use if statements to output Fizz, Buzz, and FizzBuzz in the appropriate places. It would achieve the goal of the rules, but be highly inefficient and inflexible.

The next step up might be something like this:

// FizzBuzz
package main

import (
 "fmt"
 "strconv"
)

func main() {

 // Create a loop to count 1 to 100
 for i := 1; i <= 100; i++ {

  // Create a string variable that gets reinitialized each iteration
  var strOutput string
  strOutput = ""

  // Fizz on 3
  if i%3 == 0 {
   strOutput = strOutput + "Fizz"
  }
  // Buzz on 5
  if i%5 == 0 {
   strOutput = strOutput + "Buzz"
  }
  // Otherwise, output the number
  if strOutput == "" {
   strOutput = strconv.Itoa(i)
  }
  // Print the result
  fmt.Println(strOutput)
 }

}

If you know modulo, FizzBuzz is a pretty straightforward logic problem. But what if you didn't know about that piece of math?

// fizzbuzz-simple.go
package main

import (
 "fmt"
 "strconv"
)

func main() {

 for a := 1; a <= 100; a++ {

  var strOutput string = ""

  intTmp := a / 3
  if intTmp*3 == a {
   strOutput = "Fizz"
  }

  intTmp = a / 5
  if intTmp*5 == a {
   strOutput = strOutput + "Buzz"
  }

  if strOutput == "" {
   strOutput = strconv.Itoa(a)
  }

  fmt.Println(strOutput)
 }

}

This is probably a little slower...to be honest, I'm not sure if the compiler would optimize this into similar binary algorithms. But the end result is still the same.

The first issue I'd have with the basic implementation is that it's not very modular. It might be better to use a function to determine the fizzing and the buzzing.

// fizzbuzz-func.go
package main

import (
 "fmt"
 "strconv"
)

func main() {

 // Create a loop to count 1 to 100
 for i := 1; i <= 100; i++ {

  // Fizz on 3
  strOutput := CheckMod(i, 3, "Fizz")

  // Buzz on 5
  strOutput = strOutput + CheckMod(i, 5, "Buzz")

  // Otherwise, output the number
  if strOutput == "" {
   strOutput = strconv.Itoa(i)
  }

  // Print the result
  fmt.Println(strOutput)
 }

}

func CheckMod(intCount int, intCheck int, strLabel string) string {

 if intCount%intCheck == 0 {
  return strLabel
 } else {
  return ""
 }

}

This version includes a simple CheckMod() function that can be called to see if the remainder when divided by a supplied integer should get a label; now it takes minimal editing to change the numbers for which Fizz, Buzz, or FizzBuzz are used as output!

And, of course, this still has the same output as the previous versions.

But what if we don't want to keep modifying the source code to alter the Fizz and Buzz triggers? That's simple too.

// fizzbuzz-func-flags.go
package main

import (
 "flag"
 "fmt"
 "strconv"
)

func main() {

 intCountTo := flag.Int("countto", 100, "Count from 1 to this number")
 intFirstNum := flag.Int("firstnum", 3, "First number to label")
 strFirstLabel := flag.String("firstlabel", "Fizz", "First label to substitute")
 intSecondNum := flag.Int("secondnum", 5, "Second number to label")
 strSecondLabel := flag.String("secondlabel", "Buzz", "Second label to substitute")
 flag.Parse()

 // Create a loop to count 1 to x
 for i := 1; i <= *intCountTo; i++ {

  // Fizz on y
  strOutput := CheckMod(i, *intFirstNum, *strFirstLabel)

  // Buzz on z
  strOutput = strOutput + CheckMod(i, *intSecondNum, *strSecondLabel)

  // Otherwise, output the number
  if strOutput == "" {
   strOutput = strconv.Itoa(i)
  }

  // Print the result
  fmt.Println(strOutput)
 }

}

func CheckMod(intCount int, intCheck int, strLabel string) string {

 if intCount%intCheck == 0 {
  return strLabel
 } else {
  return ""
 }

}

Now there are command line flags that designate the Fizz and the Buzz (as well as possible new labels for Fizz and Buzz) and the number to count to!

Because there are defaults added in to the flag variables, the default version of this...with no flags set at the command line...will have identical output to the previous applications.

This version added quite a bit of flexibility to the program, and that flexibility is accessible from the command line by the end user. There is another problem, though; if you intend for an end user to use this application, there should be some sanity checking for the things they can change.

// fizzbuzz-func-flags-errcheck.go
package main

import (
 "flag"
 "fmt"
 "os"
 "strconv"
)

// A struct of flags
type stctFlags struct {
 intCountTo     *int
 intFirstNum    *int
 strFirstLabel  *string
 intSecondNum   *int
 strSecondLabel *string
}

func main() {

 var strctFlags stctFlags

 strctFlags.intCountTo = flag.Int("countto", 100, "Count from 1 to this number")
 strctFlags.intFirstNum = flag.Int("firstnum", 3, "First number to label")
 strctFlags.strFirstLabel = flag.String("firstlabel", "Fizz", "First label to substitute")
 strctFlags.intSecondNum = flag.Int("secondnum", 5, "Second number to label")
 strctFlags.strSecondLabel = flag.String("secondlabel", "Buzz", "Second label to substitute")
 flag.Parse()

 EvalFlags(&strctFlags)

 // Create a loop to count 1 to 100
 for i := 1; i <= *strctFlags.intCountTo; i++ {

  // Fizz on 3
  strOutput := CheckMod(i, *strctFlags.intFirstNum, *strctFlags.strFirstLabel)

  // Buzz on 5
  strOutput = strOutput + CheckMod(i, *strctFlags.intSecondNum, *strctFlags.strSecondLabel)

  // Otherwise, output the number
  if strOutput == "" {
   strOutput = strconv.Itoa(i)
  }

  // Print the result
  fmt.Println(strOutput)
 }

}

func EvalFlags(strctFlags *stctFlags) {

 if *strctFlags.intCountTo <= 0 {

  fmt.Println("-countto must be greater than 0")
  os.Exit(1)
 }

 if *strctFlags.intFirstNum <= 0 {

  fmt.Println("-firstnum must be greater than 0")
  os.Exit(1)
 }

 if *strctFlags.strFirstLabel == "" {

  fmt.Println("-firstlabel must have a text label")
  os.Exit(1)
 }

 if *strctFlags.intSecondNum <= 0 {

  fmt.Println("-secondnum must be greater than 0")
  os.Exit(1)
 }

 if *strctFlags.strSecondLabel == "" {

  fmt.Println("-secondlabel must have a text label")
  os.Exit(1)
 }

 // Done
 return
}

func CheckMod(intCount int, intCheck int, strLabel string) string {

 if intCount%intCheck == 0 {
  return strLabel
 } else {
  return ""
 }

}

Now the application checks for things like labels being set to some kind of string and not an empty string, and all the numbers are set to something greater than 0. Basic error checking.

And once again...the output, by default, will match the output of the previous programs!

These are all rather straightforward. It doesn't really take advantage of features specific to Go, like channels (Here is the link to the Go playground implementation from Russ Cox, reproduced here:)

package main

import "fmt"

func main() {
 c := generate()
 c = filter(c, 3, "Fizz")
 c = filter(c, 5, "Buzz")
 for i := 1; i <= 100; i++ {
  if s := <-c; s != "" {
   fmt.Println(s)
  } else {
   fmt.Println(i)
  }
 }
}

func generate() <-chan string {
 c := make(chan string)
 go func() {
  for {
   c <- ""
  }
 }()
 return c
}

func filter(c <-chan string, n int, label string) <-chan string {
 out := make(chan string)
 go func() {
  for {
   for i := 0; i < n-1; i++ {
    out <- <-c
   }
   out <- <-c + label
  }
 }()
 return out
}

I should note that I created a blog past blog post that explored the channels implementation above...

The simple Fizz Buzz test in the forms above have the same output, but it's accomplished in many ways. I'm sure there are people who would be able to send variations that also have the same end result using a different algorithmic logic; logical, and possessing a strict set of rules that must conform to the expectations of the compiler, but still arriving to the same destination through different means.

To understand the source code means twisting your brain into understanding how the programmer responsible for the source code thinks and expresses his or her way of thinking against those rules of the programming language's grammar and syntax.

The examples above are a peek into some of the evolution in my own thinking about how to program a task, how my own thinking in Go had gradually focused on aspects to increase maintainability and flexibility while accomplishing a goal. I wonder if this is the kind of evolution that is looked for by interviewers for programming jobs...although that's a dangerous thought, considering that the expectation for defining the rungs of skill on that ladder of skill could be dangerously arbitrary.

I'm still refining my methods of modeling tasks when programming. I'm changing workflows, how I comment, and what I comment. I still occasionally reel back, perplexed, when seeing some samples of other people's code and have no idea why...or how...they thought the problem through the way they did.

Each sample I write or read is a reflection of the person who wrote it.

Sometimes I wonder what my own reflects about me.

More Tuning Golang Apps for High Concurrency Tasks on Linux

I have a project that is fairly straightforward. Again it's work related, so I have to fuzz some details, and again my memory is naturally fuzzy so I doubt it's an issue.

Background

This program I've been working on makes calls to a service (a REST endpoint) that in turn pulls data from a database, then my application parses that information into components and checks the disk to see if the file already exists. If it doesn't exist on disk already, the program makes a call to the API endpoint again asking for specific record information and writes it to the disk. In the end I get a huge set of files sorted in a structure resembling ./files/year/month/day/datatype/subtype/filename.txt.

There are literally millions of records to sort through. A single thread handling this would probably take weeks. Therefore, the program uses several (configurable!) goroutines to pull records simultaneously.

First Problem: Too Many Open Files

I wrote about this fix earlier in the blog, but I'll give a quick recap.

At first everything seemed fine. I have a simple bit of math being output periodically to the console, and it was chugging along at around 20,000 records/minute. The system was functioning fine, no errors were showing up. All was right with the world.

Then a few hours later a few alerts arrived in the email. At this point the utility was running on its own instance with its own storage and was making calls to a load balancer that held a few endpoint servers behind it. The only change to the system that could possibly prevent the system from making connections was the utility I was running, so I killed it, and when the API servers were checked there were still 18,000+ network connections in TIME_WAIT on each system.

Linux systems treat files on the disk as well as sockets as "open files" due to the way Linux handles file handles. Too Many Open Files can mean literally too many files are open or it can mean too many network connections are open, but it usually is a combination of the two.

Research time. The problem here is usually related to "you didn't close the connections." That wasn't the cause here. The calls were straightforward; I had a function that created a transport, created a client, made the connection, and called GET then read the data to return to the caller. It was a textbook example fragment of Go adapted to my purposes, and that included a defer Close() call so when the function exited it should make really sure everything was closed properly.

Check the "did you close the connection" off the list. And I also read the data from the socket before closing it, so that can be checked off the list. I had a hacked together bit of logic to retry connections if there was an error, but it also printed that status to the console when that happened. Nothing appeared as the too many open files errors popped up, so even if that caused a socket leak, it wasn't the likely cause.

The issue was the call to instantiate a transport each time the function was called. Transports hold the pool of client connections; the system should be re-using connections. Because the transport was destroyed each time the function returned, it was creating a new pool of connections, which meant new sets of client connections to the server instead of recycling previous connections and that led to thousands of "open files".

The solution was to create the transport and pass it as a parameter to the call to GET the web endpoint. This allowed the transport to continue to manage the client pool outside the scope of the function call, and that allowed the system to keep a managed pool of connections for re-use.

This wouldn't have shown up if I were making periodic, occasional calls to different websites every few minutes. The problem would still be there, but chances are the connections would eventually close and time out before piling up and becoming a problem.

Too Many Files Leads to Terrible Times

There are a few things that are obvious in affecting the speed information is being processed, and at the risk of sounding immodest, I've been told I'm pretty good at spotting the obvious.

Warning: I'm not a Go expert. I'm citing information here that is just my current understanding, so if I'm wrong, please correct me in the comments.

Because I'm writing files, the drive can definitely affect performance. I have multiple processes that could be trying multiple disk operations in parallel at a given time. To that end, disk seek times, write times, and cache can directly impact the utility's speed.

I'm dealing with millions of files. During the initial testing and design of the utility, I had to deal with a file that would unzip into a directory holding around 100,000 files; then I had to deal with several of those 100K-file containing directories for processing. If you haven't tried that on a Macintosh using the HFS+ filesystem, it's not fun. EXT4 doesn't really handle it well either. Even on an SSD, getting a directory listing is downright painful. Too many files in one directory is difficult for some filesystems to handle.

One solution is to split the directory into more subdirectories, reducing the number of entries the system has to track per directory. This is in fact the solution I used, splitting information into logical subsets.

Timing Out Connections

Another fun fact I learned during this project; by default, the Golang client doesn't have timeouts set. This leads to some fun havoc with stray connections left in weird states that if you're using them to hit random sites in a semi-random fashion, you'd probably never notice. Hammer the same site with hundreds of requests per second, and you can bet this can have some ramifications.

I read about this in a blog post warning against using the default settings in http.Client. After reviewing that information, I went back to the source code and added some timeouts, like so:

 tr := &http.Transport{
  Dial: (&net.Dialer{
   Timeout: 30 * time.Second,
  }).Dial,
  TLSHandshakeTimeout: 30 * time.Second,
 }

 client := &http.Client{
  Transport: tr,
  Timeout:   time.Second * 10,
 }

This is a modification I made to the most intensively-used connection set; I didn't move the transport's scope for a far less-used connection in another function, figuring that yes, they would pile up to a degree, but they should properly close and age out as closed connections. This set will hammer the server with thousands of connections in parallel.

This basically added some sane timeouts to functions that previously did not have any timeouts. This helped noticeably reduce my ghost connections disappear.

Remove a Hindrance, Create a New One

The initial run finished a few days later. I realized that there was a bug in my loop logic. There were some bad words uttered and an updated version compiled.

At this point we also moved the utility, and the volume to which data was being saved, to the same system that held the API endpoint server. Basically the server being queried for information was now also hosting the client requesting and processing results from the API queries.

This eliminated what before was creating a kind of natural bottleneck that throttled performance; hundreds of connections per second simultaneously hitting the server but separated by the network transit time. Sure, it was on the scale of tens of milliseconds (if things were working well), but it really added up.

Now the client was requesting it from the localhost. *Bam*. Within a few moments, the number of open connections (using netstat |wc -l, since I only needed a rough estimate) ballooned to 40,000 connections before this appeared on the console:

dial tcp <ip address redacted>: can't assign requested address

Because dial was in the error, it was most likely the client causing the issue. After some poking around, I ended up making two more changes.

First, I tried to make a change to the number of idle connections the client keeps open. The default is two; more than that, and the client was closing the connections in the idle pool instead of making more efficient use of re-using the clients. Again, working with random connections aren't so bad, but hammering the same IP will highlight the need to alter this (and you probably don't want to change this if you're not making a large number of frequent calls to the same host):

 tr := &http.Transport{
  Dial: (&net.Dialer{
   Timeout: 30 * time.Second,
  }).Dial,
  TLSHandshakeTimeout: 30 * time.Second,
  MaxIdleConnsPerHost: intIdleConns,
 }

The changed setting is MaxIdleConnsPerHost in the transport. Here I set it to a variable that in turn is set from the command line so I could tune it at runtime, but instead of the default 2 I set it closer to 400.

The next change was an alteration on the host server. There is some guidance on a SO question explaining some tuning tweaks, but the gist of the change I made is this...

When the TCP connection is made, the connection is made to an ephemeral port. When I have a ton of tcp connections hitting the server, it would starve the number of ephemeral ports available. The next step was to try increasing the number of ports available, and then the server could support more connections per second, hopefully at a level where the connections would close and age out properly before overloading the system.

In this case, I changed net.ipv4.ip_local_port_range from "32768 61000" to "9000 64500".  From the SO question, this means I changed the connectivity from (61000-32768)/60 = 470 sockets/second to (64500-9000)/60 = 925 sockets/second.

There was another change I could make from the page that involved changing the net.ipv4.tcp_fin_timeout setting, along with a couple of others. I avoided that, opting instead to test these changes because the tuning advice was more like "change this on the client" or "change this on the server", not really geared to a situation where the server and client were eating resources on the same host. Making minimal changes to keep it working, for this project, would be fine.

I ran netstat in a loop while the application ran again. This time the open connections quickly climbed to 70,000 connections before leveling out, and it held steady. After 15 hours of elapsed runtime, it had 3 connection errors show up. Otherwise it kept up with the load just fine.

I should also mention that I ran 4 parallel processing tasks, one for each core. When I boosted that number it seemed to be a hindrance to the processing speed; keeping it at 4, the estimated processing speed was over 100K records/minute, easily holding sustained bursts 5 or 6 times the processing speed when the client was on a separate machine.

This Was a Minimal Set of Changes

There were a number of lessons learned so far; above the basic novice checking that connections are properly read from a network client response before calling Close(), be aware that the transport is what controls the pool of connection clients for efficient re-use. 

Next, be aware that by default timeouts are missing from the transport and client. Add them. 

Also if you're hitting a particular server or set of servers with requests, change your MaxIdleConnsPerHost. Otherwise you're wasting connection use.

Last, an easy way to boost connection rates is to increase the number of ephemeral ports available. There are limits to this...and you don't want to starve other resources by taking away those ports from other clients or servers on the host.

There are plenty of other changes that can be made to increase horsepower of your servers. Some additional changes are in the SO question I linked to; another good blog post discusses how MigratoryData scaled servers to 12 million concurrent connections. I'd only caution that not every task requires this kind of engineering and you might want to exercise restraint in changing things when a few tweaks can accomplish decent performance for your use case. 

Performance is a scale. Some things can be overcome with throwing lots of hardware at it. Sometimes a few tweaks will make your app run 5 or 6 times faster. 

Happy tuning!

Golang: HTTP Client Opens Too Many Sockets ("Too many open files")

This relates to a project that is work related, so I have to fuzz some of the details. But on the other hand, some details are naturally fuzzed because I have to remember some of the details and my memory is naturally fuzzy...

I'm working on a utility that is, on the surface, simple. It makes a call to an API endpoint using the http.Client, compares some quick results, and if certain conditions are met it makes a series of API calls to save the JSON responses.

The processing/checking process is carried out in a set of goroutines because the comparisons are easy to do in parallel. If the routine needs to pull a JSON reply, it calls a function that is laid out pretty much like the standard examples from the "here's how you get a web page in Go!" sites.

func GetReply(strAPI string, strServer string) string {

    // The URL to request
    strURL := strServer + “/service/" + strAPI

        // Also add timeouts for connections
        tr := &http.Transport{
            Dial: (&net.Dialer{
               Timeout: 5 * time.Second,
            }).Dial,
            TLSHandshakeTimeout: 5 * time.Second,
        }
    client := &http.Client{
        Transport: tr,
        Timeout:   time.Second * 10,
    }

    // Turn it into a request
    req, err := http.NewRequest("GET", strURL, nil)
    if err != nil {
        fmt.Println("\nError forming request: " + err.Error())
        return ""
    }
    req.Header.Set("Content-Type", "application/json")
    req.Header.Set("Accept", "application/json")

    // Get the URL
    res, err := client.Do(req)
    if err != nil {
        fmt.Println("\nError reading response body: " + err.Error())
        if res != nil {
            res.Body.Close()
        }
        return ""
    }

    // What was the response status from the server?
    var strResult string
    if res.StatusCode != 200 {
        fmt.Println("\nError reading response body, status code: " + res.Status)
        if res != nil {
            res.Body.Close()
        }
        return ""
    }

    // Read the reply
    body, err := ioutil.ReadAll(res.Body)
    if err != nil {
        fmt.Println("\nError reading response body: " + err.Error())
        if res != nil {
            res.Body.Close()
        }
        return ""  
   }
    res.Body.Close()

    // Cut down on calls to convert this
    strResult = string(body)

    // Done
    return strResult

}

This is actually a modified version of what I've pulled from various tutorials and examples, adding more calls to Close() and doing a check for whether res is nil before performing that call in an error.

I also added a timeout to the client because by default it is set to 0; no timeout. As you can probably guess this version was modified while troubleshooting.

After a few hours of the application running we had alerts come in about failing functions on the production servers. When I opened logs I discovered a number of "too many files open" errors, and a developer on the call said there were over 18,000 socket connections on each of the balanced servers.

The only difference was my use of this test program, so I killed it. The socket count fell.

Welp...guess we found the cause. But why?

There are a couple basics for beginners when using http.Client requests.
1) Close the response body after reading.
2) Clients are reused.
3) If you defer a call to Close() (as this one originally did, and most tutorials show) the function should call Close() when the function returns. The modified sample I posted simply closes it after reading the Body and checking for errors.

At first I thought it was due to clients not closing; they must close in order to be re-used. I traced the execution path a dozen ways and added more explicit Close()'s in error checks...but those errors were never printing anything during the run, so errors shouldn't be causing spill of sockets.

I added timeouts to the client and dialer. While that didn't hurt and probably made things a little cleaner, it still didn't help the too many open files/sockets error.

Another lead came from a close reading of a Stack Overflow answer. The function is creating a new Transport, tr, with each call. That Transport is what holds the Clients pool for reuse. See where I'm going with that?

Another answer on that page talked about creating a global client for his functions to reuse.

The theme was scope of variables matters when dealing with what allows re-use. Because I'm hitting the same server repeatedly and the function kept re-instantiating the mechanism that was used to govern client re-use,  the number of new connections and left-open sockets ballooned.

My next move was to go to the goroutines that were in charge of processing the replies from the API endpoints and have them create Transport instances, then when they call the function they passed the Transport as a parameter.

I uploaded the program to a remote system instance and re-ran it while watching netstat on the server and the client systems. After initially ballooning to about 4,000 connections it soon settled down to well under 100 connections (using netstat |wc -l).

Takeaways:
1) Modify the default client, and maybe the transport dialer, to add sane timeouts.
2) If you're hitting the same server repeatedly, do it all within the same scope as your transport instantiation or create a transport and pass it as a parameter to functions so you optimize the re-use of the client pool
3) Check that you properly close the response body so the client can be re-used. Check in error paths that it can be properly closed without panicking.

What about separating not just the Transport, but also the Client, then passing the Client around as a parameter? I didn't test that because I wasn't sure how "goroutine-safe" that would be against race conditions, despite the one answer on that Stack Overflow that demonstrated using a global Client instance for use.  It's possible it works fine. At this point it looks like passing the Transport worked fine, though.

I'll also note that my usual self-loathing and insecurity isn't getting the better of me this time because the top answer on that question that inspired me to try this solution was the usual advice I found repeatedly in other sites and blogs (and SO answers); check that you close your response properly. It's the top answer by a significant margin. It was almost an afterthought to realize that maybe what I was doing was pummeling one particular website with multiple instantiations of Client pools so Client reuse was a minimum.

Happy HTTP Client-ing!

Learning By Creating Support Applications

Not long ago I started a job with a company whose primary product is a very custom application that is comprised of many smaller interoperating applications. Without getting into too much detail, the applications communicate through various APIs, many of which are not well documented.

(What follows are thoughts that are not focused solely on the new employer, but rather a set of experiences I've gathered over the years from several jobs and interactions with others in the technology field. In other words, this isn't about the current employer. It's a conglomeration of experiences, and it's my own opinion. Just figured I'd have to clarify that...)

As a company focuses on growth, there comes a time when maintenance and monitoring is moved to staff that are dedicated to those tasks so the developers no longer have to do triple duty; for the new hire tasked with pioneering that position, gathering statistics to get a feel for the behavior of their systems over time, and taking care of regular maintenance and basic troubleshooting is very daunting when there is little (or no) documentation available outlining how to get the necessary metrics for gauging the health of the system.

And it isn't just a lack of documentation that acts as an obstacle. When a software-based company is first conceived and grows, it's natural for the programmers to work on getting the product into a usable, testable state. This means overcoming problems as they arise and focusing on results, not laying framework for delegating future operations.

That fosters institutional knowledge. The more of your system that is developed in-house, the more information future maintainers must glean about your system without help of outside references. Sites like Serverfault can help when you're trying to figure out why a new deployment of Nginx won't work, but it won't be useful when a log contains output from a Java application Bob, three desks away, wrote while debugging a particular reply encountered from another subsystem's API response.

Small companies with a small number of developers may feel it is inconvenient to be interrupted by the new person's constant questions about why application A is dependant on application B, or how application C discovers a service status on server 3. As a new hire, I feel a little hesitant to approach others with these types of questions, preferring to try looking for answers through other means before taking someone else's time.

(In my opinion, if the answer is to check the source code from the repo and read that to get the answers, you may as well have hired a new programmer; recognizing a need for someone dedicated to operating and maintaining your system outside the coterie of coders is a sign that there may be a need to dedicate time to documenting and tooling the application for non-programmer use.)

How can a new hire get a grasp on this situation?

In this case, I've been writing a series of Nagios plugins specifically configured to pull metrics from the various subsystems in the company application. There are cases where I thought a simple task was actually more nuanced that first appeared; each time, I ended up discovering something more about the operation of the system, and I made sure it was documented for later reference.

Each time there's a failure case, I would make a note and start work on a new monitor so we'd know about it in the future. These monitors didn't just collect a snapshot of the current state of a service, it would gather some metric that was then sent to a database and from there plotted on a graphing application for performance monitoring.

The current product relies on database performance; some queries behave different from others, where some are straightforward and others require processing of filters. Some of my checks measure response times.

Others are querying API endpoints for replies of what the services believe are their current health states.

Some queries are pulling the status of database indexing.

In cases where the application is exposing information through Java beans, my plugins are pulling numbers from JMX and checking for values within established expectations.

In other cases, plugins are checking for the existence of files that are supposed to be regularly updated and when certain records are updated in the database.

Each of these plugins, once finished and deployed, are being documented for operation in a way that when new people are hired he or she should be able to easily find a list of how these work and gather indirect information on some aspects of the in-house application operation without programmer-level institutional knowledge.

In the case of my new position, I've gained a higher respect for the value of meta-applications in gaining insight on how a complicated system works. Having information written out or explained to you is enlightening, and I never feel that documenting how something works is a waste of time. But until you find yourself executing on that knowledge, I'm not sure you really understand the subject. Creating support applications that meaningfully interact with the system pushes knowledge into the realm of wisdom the way reading about the science of flight comes alive after building your first remote control plane.

When confronted with the task of comprehending the colossal, try learning about the limited first with applications that monitor and interact with small aspects of the system. Not only will others benefit with the support applications, but you'll benefit with the mental exercise and in the end have a better model of how everything works!

Golang: Remember This When Using Select For Monitoring Channels

I thought I would share something that's easy to overlook when using a loop to listen for messages from channels in Go.

The following is a simple code snippet:

for {

    for a := range structOfChannels {

        select {

        case msg := <- structOfChannels[a].Chan1:

            // Something

        case msg := <- structofChannels[a].Chan2:

            // Something

        default:

        }

    }

}

All this is doing is rotating over a series of channels for a message and processing them. The default case makes sure the loop doesn't get stuck after the first iteration of "select", and the for without conditions means continue until eternity.

I noticed, when running Activity Monitor (this was using Go 1.8 on OS X) that the processor would stay near 100%. The system seemed responsive, but the processor staying that high was, to me, annoying.

The solution was simple; make the loop wait a fraction of a second each iteration.

for {

    tmTimer := time.NewTimer(time.Millisecond * 50)

    <-tmTimer.C

    for a := range structOfChannels {

        select {

        case msg := <- structOfChannels[a].Chan1:

            // Something

        case msg := <- structofChannels[a].Chan2:

            // Something

        default:

        }

    }

}

This just makes the loop wait 50 milliseconds before ranging again, a pause smaller than most humans would perceive but enough for the computer that it dropped the processor use to near nothing. 

There are a few other approaches that work, but have a similar effect. For example, if you're worried about the overhead of creating and freeing the NewTimer(), you could create a NewTicker() outside the for{} scope and keep reusing that. You can also probably lower the milliseconds to smaller values and see where the processor starts kicking up, but I'll leave that to the reader to experiment and tune.

The point is, because the system seemed responsive, it was easy to overlook the effect of a simple for{} loop used to monitor messages from goroutines and there's a possibility this could have an effect when deploying to servers. Check your performance when testing your work!